fix: Add namespace-specific levels support to logger (#22619)

* Add namespaced levels for logger. Add NS to mqtt. Deprecate 'warn'.

* Improve setting validation.

* Fix setting through frontend

* Support reload + frontend improvements

* update description

* remove requiresRestart

* Fix tests.

* Fix namespaced logging at lower levels. Add better tests.

---------

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

lib/extension/bridge.ts

@@ -203,6 +203,10 @@ export default class Bridge extends Extension {
             logger.setLevel(newSettings.advanced.log_level);
         }
 
+        if (newSettings.advanced?.log_namespaced_levels != undefined) {
+            logger.setNamespacedLevels(newSettings.advanced.log_namespaced_levels);
+        }
+
         if (newSettings.advanced?.log_debug_namespace_ignore != undefined) {
             logger.setDebugNamespaceIgnore(newSettings.advanced.log_debug_namespace_ignore);
         }
@@ -358,10 +362,9 @@ export default class Bridge extends Extension {
 
     // Deprecated
     @bind async configLogLevel(message: KeyValue | string): Promise<MQTTResponse> {
-        const allowed = ['error', 'warn', 'info', 'debug'];
-        const value = this.getValue(message) as 'error' | 'warn' | 'info' | 'debug';
-        if (typeof value !== 'string' || !allowed.includes(value)) {
-            throw new Error(`'${value}' is not an allowed value, allowed: ${allowed}`);
+        const value = this.getValue(message) as settings.LogLevel;
+        if (typeof value !== 'string' || !settings.LOG_LEVELS.includes(value)) {
+            throw new Error(`'${value}' is not an allowed value, allowed: ${settings.LOG_LEVELS}`);
         }
 
         logger.setLevel(value);

lib/extension/homeassistant.ts

@@ -1911,7 +1911,7 @@ export default class HomeAssistant extends Extension {
                     command_topic: `${baseTopic}/request/options`,
                     command_template:
                         '{"options": {"advanced": {"log_level": "{{ value }}" } } }',
-                    options: ['info', 'warn', 'error', 'debug'],
+                    options: settings.LOG_LEVELS,
                 },
             },
             // Sensors:

lib/extension/legacy/bridgeLegacy.ts

@@ -8,7 +8,6 @@ import bind from 'bind-decorator';
 
 const configRegex =
     new RegExp(`${settings.get().mqtt.base_topic}/bridge/config/((?:\\w+/get)|(?:\\w+/factory_reset)|(?:\\w+))`);
-const allowedLogLevels = ['error', 'warn', 'info', 'debug'];
 
 export default class BridgeLegacy extends Extension {
     private lastJoinedDeviceName: string = null;
@@ -118,12 +117,12 @@ export default class BridgeLegacy extends Extension {
     }
 
     @bind logLevel(topic: string, message: string): void {
-        const level = message.toLowerCase() as 'error' | 'warn' | 'info' | 'debug';
-        if (allowedLogLevels.includes(level)) {
+        const level = message.toLowerCase() as settings.LogLevel;
+        if (settings.LOG_LEVELS.includes(level)) {
             logger.info(`Switching log level to '${level}'`);
             logger.setLevel(level);
         } else {
-            logger.error(`Could not set log level to '${level}'. Allowed level: '${allowedLogLevels.join(',')}'`);
+            logger.error(`Could not set log level to '${level}'. Allowed level: '${settings.LOG_LEVELS.join(',')}'`);
         }
 
         this.publish();

lib/mqtt.ts

@@ -6,6 +6,8 @@ import fs from 'fs';
 import bind from 'bind-decorator';
 import type {QoS} from 'mqtt-packet';
 
+const NS = 'z2m:mqtt';
+
 export default class MQTT {
     private publishedTopics: Set<string> = new Set();
     private connectionTimer: NodeJS.Timeout;
@@ -22,7 +24,7 @@ export default class MQTT {
 
     async connect(): Promise<void> {
         const mqttSettings = settings.get().mqtt;
-        logger.info(`Connecting to MQTT server at ${mqttSettings.server}`);
+        logger.info(`Connecting to MQTT server at ${mqttSettings.server}`, NS);
 
         const options: mqtt.IClientOptions = {
             will: {
@@ -38,37 +40,37 @@ export default class MQTT {
         }
 
         if (mqttSettings.keepalive) {
-            logger.debug(`Using MQTT keepalive: ${mqttSettings.keepalive}`);
+            logger.debug(`Using MQTT keepalive: ${mqttSettings.keepalive}`, NS);
             options.keepalive = mqttSettings.keepalive;
         }
 
         if (mqttSettings.ca) {
-            logger.debug(`MQTT SSL/TLS: Path to CA certificate = ${mqttSettings.ca}`);
+            logger.debug(`MQTT SSL/TLS: Path to CA certificate = ${mqttSettings.ca}`, NS);
             options.ca = fs.readFileSync(mqttSettings.ca);
         }
 
         if (mqttSettings.key && mqttSettings.cert) {
-            logger.debug(`MQTT SSL/TLS: Path to client key = ${mqttSettings.key}`);
-            logger.debug(`MQTT SSL/TLS: Path to client certificate = ${mqttSettings.cert}`);
+            logger.debug(`MQTT SSL/TLS: Path to client key = ${mqttSettings.key}`, NS);
+            logger.debug(`MQTT SSL/TLS: Path to client certificate = ${mqttSettings.cert}`, NS);
             options.key = fs.readFileSync(mqttSettings.key);
             options.cert = fs.readFileSync(mqttSettings.cert);
         }
 
         if (mqttSettings.user && mqttSettings.password) {
-            logger.debug(`Using MQTT login with username: ${mqttSettings.user}`);
+            logger.debug(`Using MQTT login with username: ${mqttSettings.user}`, NS);
             options.username = mqttSettings.user;
             options.password = mqttSettings.password;
         } else {
-            logger.debug(`Using MQTT anonymous login`);
+            logger.debug(`Using MQTT anonymous login`, NS);
         }
 
         if (mqttSettings.client_id) {
-            logger.debug(`Using MQTT client ID: '${mqttSettings.client_id}'`);
+            logger.debug(`Using MQTT client ID: '${mqttSettings.client_id}'`, NS);
             options.clientId = mqttSettings.client_id;
         }
 
         if (mqttSettings.hasOwnProperty('reject_unauthorized') && !mqttSettings.reject_unauthorized) {
-            logger.debug(`MQTT reject_unauthorized set false, ignoring certificate warnings.`);
+            logger.debug(`MQTT reject_unauthorized set false, ignoring certificate warnings.`, NS);
             options.rejectUnauthorized = false;
         }
 
@@ -85,7 +87,7 @@ export default class MQTT {
             });
 
             this.client.on('error', (err) => {
-                logger.error(`MQTT error: ${err.message}`);
+                logger.error(`MQTT error: ${err.message}`, NS);
                 reject(err);
             });
             this.client.on('message', this.onMessage);
@@ -97,11 +99,11 @@ export default class MQTT {
         clearTimeout(this.connectionTimer);
         this.connectionTimer = setInterval(() => {
             if (this.client.reconnecting) {
-                logger.error('Not connected to MQTT server!');
+                logger.error('Not connected to MQTT server!', NS);
             }
         }, utils.seconds(10));
 
-        logger.info('Connected to MQTT server');
+        logger.info('Connected to MQTT server', NS);
         await this.publishStateOnline();
 
         if (!this.initialConnect) {
@@ -126,7 +128,7 @@ export default class MQTT {
         await this.publish('bridge/state', utils.availabilityPayload('offline', settings.get()),
             {retain: true, qos: 0});
         this.eventBus.removeListeners(this);
-        logger.info('Disconnecting from MQTT server');
+        logger.info('Disconnecting from MQTT server', NS);
         this.client?.end();
     }
 
@@ -137,7 +139,7 @@ export default class MQTT {
     @bind public onMessage(topic: string, message: Buffer): void {
         // Since we subscribe to zigbee2mqtt/# we also receive the message we send ourselves, skip these.
         if (!this.publishedTopics.has(topic)) {
-            logger.debug(`Received MQTT message on '${topic}' with data '${message.toString()}'`);
+            logger.debug(`Received MQTT message on '${topic}' with data '${message.toString()}'`, NS);
             this.eventBus.emitMQTTMessage({topic, message: message.toString()});
         }
 
@@ -175,14 +177,14 @@ export default class MQTT {
         if (!this.isConnected()) {
             /* istanbul ignore else */
             if (!skipLog) {
-                logger.error(`Not connected to MQTT server!`);
-                logger.error(`Cannot send message: topic: '${topic}', payload: '${payload}`);
+                logger.error(`Not connected to MQTT server!`, NS);
+                logger.error(`Cannot send message: topic: '${topic}', payload: '${payload}`, NS);
             }
             return;
         }
 
         if (!skipLog) {
-            logger.debug(`MQTT publish: topic '${topic}', payload '${payload}'`);
+            logger.info(`MQTT publish: topic '${topic}', payload '${payload}'`, NS);
         }
 
         const actualOptions: mqtt.IClientPublishOptions = {...defaultOptions, ...options};

lib/types/types.d.ts

@@ -1,4 +1,5 @@
 /* eslint-disable camelcase */
+import {LogLevel} from 'lib/util/settings';
 import type {
     Device as ZHDevice,
     Group as ZHGroup,
@@ -191,7 +192,8 @@ declare global {
             log_output: ('console' | 'file' | 'syslog')[],
             log_directory: string,
             log_file: string,
-            log_level: 'debug' | 'info' | 'error' | 'warn',
+            log_level: LogLevel,
+            log_namespaced_levels: Record<string, LogLevel>,
             log_syslog: KeyValue,
             log_debug_to_mqtt_frontend: boolean,
             log_debug_namespace_ignore: string,

lib/util/logger.ts

@@ -7,16 +7,14 @@ import fx from 'mkdir-recursive';
 import {rimrafSync} from 'rimraf';
 import assert from 'assert';
 
-const LOG_LEVELS = ['error', 'warning', 'info', 'debug'] as const;
-type LogLevel = typeof LOG_LEVELS[number];
-
 class Logger {
-    private level: LogLevel;
+    private level: settings.LogLevel;
     private output: string[];
     private directory: string;
     private logger: winston.Logger;
     private fileTransport: winston.transports.FileTransportInstance;
     private debugNamespaceIgnoreRegex?: RegExp;
+    private namespacedLevels: Record<string, settings.LogLevel>;
 
     public init(): void {
         // What transports to enable
@@ -25,20 +23,18 @@ class Logger {
         const timestamp = moment(Date.now()).format('YYYY-MM-DD.HH-mm-ss');
         this.directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', timestamp);
         const 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
-        this.level = settingLevel === 'warn' ? 'warning' : settingLevel;
+        this.level = settings.get().advanced.log_level;
+        this.namespacedLevels = settings.get().advanced.log_namespaced_levels;
 
         assert(
-            LOG_LEVELS.includes(this.level),
-            `'${this.level}' is not valid log_level, use one of '${LOG_LEVELS.join(', ')}'`,
+            settings.LOG_LEVELS.includes(this.level),
+            `'${this.level}' is not valid log_level, use one of '${settings.LOG_LEVELS.join(', ')}'`,
         );
 
         const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format);
 
         this.logger = winston.createLogger({
-            level: this.level,
+            level: 'debug',
             format: winston.format.combine(
                 winston.format.errors({stack: true}),
                 winston.format.timestamp({format: timestampFormat}),
@@ -81,9 +77,8 @@ class Logger {
             // Add file logger when enabled
             // eslint-disable-next-line max-len
             // NOTE: the initiation of the logger even when not added as transport tries to create the logging directory
-            const transportFileOptions: KeyValue = {
+            const transportFileOptions: winston.transports.FileTransportOptions = {
                 filename: path.join(this.directory, logFilename),
-                json: false,
                 format: winston.format.printf(/* istanbul ignore next */(info) => {
                     return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
                 }),
@@ -131,7 +126,6 @@ class Logger {
     }
 
     public addTransport(transport: winston.transport): void {
-        transport.level = this.level;
         this.logger.add(transport);
     }
 
@@ -147,41 +141,48 @@ class Logger {
         this.debugNamespaceIgnoreRegex = value != '' ? new RegExp(value) : undefined;
     }
 
-    // TODO refactor Z2M level to 'warning' to simplify logic
-    public getLevel(): LogLevel | 'warn' {
-        return this.level === 'warning' ? 'warn' : this.level;
+    public getLevel(): settings.LogLevel {
+        return this.level;
     }
 
-    public setLevel(level: LogLevel | 'warn'): void {
-        if (level === 'warn') {
-            level = 'warning';
+    public setLevel(level: settings.LogLevel): void {
+        this.level = level;
+    }
+
+    public getNamespacedLevels(): Record<string, settings.LogLevel> {
+        return this.namespacedLevels;
+    }
+
+    public setNamespacedLevels(nsLevels: Record<string, settings.LogLevel>): void {
+        this.namespacedLevels = nsLevels;
+    }
+
+    private log(level: settings.LogLevel, message: string, namespace: string): void {
+        const nsLevel = this.namespacedLevels[namespace] ?? this.level;
+
+        if (settings.LOG_LEVELS.indexOf(level) <= settings.LOG_LEVELS.indexOf(nsLevel)) {
+            this.logger.log(level, message, {namespace});
         }
+    }
 
-        this.level = level;
-        this.logger.transports.forEach((transport) => transport.level = this.level);
+    public error(message: string, namespace: string = 'z2m'): void {
+        this.log('error', message, namespace);
     }
 
     public warning(message: string, namespace: string = 'z2m'): void {
-        this.logger.warning(message, {namespace});
+        this.log('warning', message, namespace);
     }
 
     public info(message: string, namespace: string = 'z2m'): void {
-        this.logger.info(message, {namespace});
+        this.log('info', message, namespace);
     }
 
     public debug(message: string, namespace: string = 'z2m'): void {
-        if (this.level !== 'debug') {
-            return;
-        }
         if (this.debugNamespaceIgnoreRegex?.test(namespace)) {
             return;
         }
 
-        this.logger.debug(message, {namespace});
-    }
-
-    public error(message: string, namespace: string = 'z2m'): void {
-        this.logger.error(message, {namespace});
+        this.log('debug', message, namespace);
     }
 
     // Cleanup any old log directory.

lib/util/settings.schema.json

@@ -492,11 +492,28 @@
         },
         "log_level": {
           "type": "string",
-          "enum": ["info", "warn", "error", "debug"],
+          "enum": ["error", "warning", "info", "debug"],
           "title": "Log level",
           "description": "Logging level",
           "default": "info"
         },
+        "log_namespaced_levels": {
+          "type": "object",
+          "propertyNames": {
+            "pattern": "^(z2m|zhc|zh)(:[a-z0-9]{1,})*$"
+          },
+          "additionalProperties": {
+            "type": "string",
+            "enum": ["error", "warning", "info", "debug"]
+          },
+          "title": "Log Namespaced Levels",
+          "description": "Set individual log levels for certain namespaces",
+          "default": {},
+          "examples": [
+            {"z2m:mqtt": "warning"},
+            {"zh:ember:uart:ash": "info"}
+          ]
+        },
         "log_debug_to_mqtt_frontend": {
           "type": "boolean",
           "title": "Log debug to MQTT and frontend",

lib/util/settings.ts

@@ -26,6 +26,10 @@ objectAssignDeep(schema, schemaJson);
     delete schemaJson.properties.ban;
 }
 
+/** NOTE: by order of priority, lower index is lower level (more important) */
+export const LOG_LEVELS: readonly string[] = ['error', 'warning', 'info', 'debug'] as const;
+export type LogLevel = typeof LOG_LEVELS[number];
+
 // DEPRECATED ZIGBEE2MQTT_CONFIG: https://github.com/Koenkk/zigbee2mqtt/issues/4697
 const file = process.env.ZIGBEE2MQTT_CONFIG ?? data.joinPath('configuration.yaml');
 const ajvSetting = new Ajv({allErrors: true}).addKeyword('requiresRestart').compile(schemaJson);
@@ -82,6 +86,7 @@ const defaults: RecursivePartial<Settings> = {
         log_directory: path.join(data.getPath(), 'log', '%TIMESTAMP%'),
         log_file: 'log.log',
         log_level: /* istanbul ignore next */ process.env.DEBUG ? 'debug' : 'info',
+        log_namespaced_levels: {},
         log_syslog: {},
         log_debug_to_mqtt_frontend: false,
         log_debug_namespace_ignore: '',
@@ -186,6 +191,10 @@ function loadSettingsWithDefaults(): void {
         _settingsWithDefaults.advanced.output = _settings.experimental.output;
     }
 
+    if (_settings.advanced?.log_level === 'warn') {
+        _settingsWithDefaults.advanced.log_level = 'warning';
+    }
+
     // @ts-ignore
     _settingsWithDefaults.ban && _settingsWithDefaults.blocklist.push(..._settingsWithDefaults.ban);
     // @ts-ignore