From 3c1a4afcb723eecccf6ab9c3e04e1e0eca7b2cbb Mon Sep 17 00:00:00 2001 From: Nerivec <62446222+Nerivec@users.noreply.github.com> Date: Sun, 7 Apr 2024 20:52:55 +0200 Subject: [PATCH] fix: Convert logger into a class (#22129) --- lib/controller.ts | 2 - lib/util/logger.ts | 328 ++++++++++++++++++++++---------------------- test/logger.test.js | 55 +++----- 3 files changed, 182 insertions(+), 203 deletions(-) diff --git a/lib/controller.ts b/lib/controller.ts index ca32921f6f..ea5e3a1549 100644 --- a/lib/controller.ts +++ b/lib/controller.ts @@ -60,7 +60,6 @@ export class Controller { private extensionArgs: ExtensionArgs; constructor(restartCallback: () => void, exitCallback: (code: number, restart: boolean) => void) { - logger.init(); zhSetLogger(logger); zhcSetLogger(logger); this.eventBus = new EventBus(); @@ -99,7 +98,6 @@ export class Controller { async start(): Promise { this.state.start(); - logger.logOutput(); const info = await utils.getZigbee2MQTTVersion(); logger.info(`Starting Zigbee2MQTT version ${info.version} (commit #${info.commitHash})`); diff --git a/lib/util/logger.ts b/lib/util/logger.ts index f0a30eb8e7..24cc3467dc 100644 --- a/lib/util/logger.ts +++ b/lib/util/logger.ts @@ -10,34 +10,48 @@ import assert from 'assert'; const LOG_LEVELS = ['error', 'warning', 'info', 'debug'] as const; type LogLevel = typeof LOG_LEVELS[number]; -let logger: winston.Logger; -let fileTransport : winston.transport; -let output: string[]; -let directory: string; -let logFilename: string; -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'), +class Logger { + private level: LogLevel; + private readonly output: string[]; + private readonly directory: string; + private readonly logger: winston.Logger; + private readonly fileTransport: winston.transports.FileTransportInstance; + + constructor() { + // What transports to enable + this.output = settings.get().advanced.log_output; + // Directory to log to + 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; + + assert( + LOG_LEVELS.includes(this.level), + `'${this.level}' is not valid log_level, use one of '${LOG_LEVELS.join(', ')}'`, + ); + + const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format); + + this.logger = winston.createLogger({ + level: this.level, + format: winston.format.combine( + winston.format.errors({stack: true}), + winston.format.timestamp({format: timestampFormat}), + ), + levels: winston.config.syslog.levels, + }); + + const consoleSilenced = !this.output.includes('console'); + // Print to user what logging is active + let logging = `Logging to console${consoleSilenced ? ' (silenced)' : ''}`; + + // Setup default console logger + this.logger.add(new winston.transports.Console({ + silent: consoleSilenced, // winston.config.syslog.levels sets 'warning' as 'red' format: winston.format.combine( winston.format.colorize({colors: {debug: 'blue', info: 'green', warning: 'yellow', error: 'red'}}), @@ -45,167 +59,157 @@ function init(): void { return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`; }), ), - }), - ]; - - 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) { - const current = settings.get().advanced.log_directory.replace('%TIMESTAMP%', 'current'); - const actual = './' + timestamp; - /* istanbul ignore next */ - if (fs.existsSync(current)) { - fs.unlinkSync(current); + })); + + if (this.output.includes('file')) { + logging += `, file (filename: ${logFilename})`; + + // Make sure that log directory exists when not logging to stdout only + fx.mkdirSync(this.directory); + + if (settings.get().advanced.log_symlink_current) { + const current = settings.get().advanced.log_directory.replace('%TIMESTAMP%', 'current'); + const actual = './' + timestamp; + /* istanbul ignore next */ + if (fs.existsSync(current)) { + fs.unlinkSync(current); + } + fs.symlinkSync(actual, current); } - fs.symlinkSync(actual, current); - } - // 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.printf(/* istanbul ignore next */(info) => { - return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`; - }), - }; - - if (settings.get().advanced.log_rotation) { - transportFileOptions.tailable = true; - transportFileOptions.maxFiles = 3; // Keep last 3 files - transportFileOptions.maxsize = 10000000; // 10MB - } + // 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 = { + 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}`; + }), + }; - fileTransport = new winston.transports.File(transportFileOptions); - transportsToUse.push(fileTransport); - } + if (settings.get().advanced.log_rotation) { + transportFileOptions.tailable = true; + transportFileOptions.maxFiles = 3; // Keep last 3 files + transportFileOptions.maxsize = 10000000; // 10MB + } - /* istanbul ignore next */ - 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.namespace}: ${info.message}`; - }), - ...settings.get().advanced.log_syslog, - }; - - if (options.hasOwnProperty('type')) { - options.type = options.type.toString(); + this.fileTransport = new winston.transports.File(transportFileOptions); + this.logger.add(this.fileTransport); } - // @ts-expect-error custom transport - transportsToUse.push(new winston.transports.Syslog(options)); - } + /* istanbul ignore next */ + if (this.output.includes('syslog')) { + logging += `, syslog`; + // eslint-disable-next-line + require('winston-syslog').Syslog; - logger = winston.createLogger({ - format: winston.format.combine( - winston.format.errors({stack: true}), - winston.format.timestamp({format: timestampFormat}), - ), - transports: transportsToUse, - levels: winston.config.syslog.levels, - }); -} + const options: KeyValue = { + app_name: 'Zigbee2MQTT', + format: winston.format.printf(/* istanbul ignore next */(info) => { + return `${info.namespace}: ${info.message}`; + }), + ...settings.get().advanced.log_syslog, + }; -function addTransport(transport: winston.transport): void { - transport.level = transportsToUse[0].level; - logger.add(transport); -} + if (options.hasOwnProperty('type')) { + options.type = options.type.toString(); + } -function removeTransport(transport: winston.transport): void { - logger.remove(transport); -} + // @ts-expect-error untyped transport + this.logger.add(new winston.transports.Syslog(options)); + } -// TODO refactor Z2M level to 'warning' to simplify logic -function getLevel(): LogLevel | 'warn' { - let level = transportsToUse[0].level; + this.info(logging); + } - if (level === 'warning') { - level = 'warn'; + get winston(): winston.Logger { + return this.logger; } - return transportsToUse[0].level as LogLevel | 'warn'; -} + public addTransport(transport: winston.transport): void { + transport.level = this.level; + this.logger.add(transport); + } -function setLevel(level: LogLevel | 'warn'): void { - if (level === 'warn') { - level = 'warning'; + public removeTransport(transport: winston.transport): void { + this.logger.remove(transport); } - logger.transports.forEach((transport) => transport.level = level); -} + // TODO refactor Z2M level to 'warning' to simplify logic + public getLevel(): LogLevel | 'warn' { + return this.level === 'warning' ? 'warn' : this.level; + } -function warning(message: string, namespace: string = 'z2m'): void { - logger.warning(message, {namespace}); -} + public setLevel(level: LogLevel | 'warn'): void { + if (level === 'warn') { + level = 'warning'; + } -function info(message: string, namespace: string = 'z2m'): void { - logger.info(message, {namespace}); -} + this.level = level; + this.logger.transports.forEach((transport) => transport.level = this.level); + } -function debug(message: string, namespace: string = 'z2m'): void { - logger.debug(message, {namespace}); -} + public warning(message: string, namespace: string = 'z2m'): void { + this.logger.warning(message, {namespace}); + } -function error(message: string, namespace: string = 'z2m'): void { - logger.error(message, {namespace}); -} + public info(message: string, namespace: string = 'z2m'): void { + this.logger.info(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}.`); -} + public debug(message: string, namespace: string = 'z2m'): void { + if (this.level !== 'debug') { + return; + } -// Cleanup any old log directory. -function cleanup(): void { - if (settings.get().advanced.log_directory.includes('%TIMESTAMP%')) { - const rootDirectory = path.join(directory, '..'); + this.logger.debug(message, {namespace}); + } - let directories = fs.readdirSync(rootDirectory).map((d) => { - d = path.join(rootDirectory, d); - return {path: d, birth: fs.statSync(d).mtime}; - }); + public error(message: string, namespace: string = 'z2m'): void { + this.logger.error(message, {namespace}); + } - directories.sort((a: KeyValue, b: KeyValue) => b.birth - a.birth); - directories = directories.slice(10, directories.length); - directories.forEach((dir) => { - debug(`Removing old log directory '${dir.path}'`); - rimrafSync(dir.path); - }); + // Cleanup any old log directory. + public cleanup(): void { + if (settings.get().advanced.log_directory.includes('%TIMESTAMP%')) { + const rootDirectory = path.join(this.directory, '..'); + + let directories = fs.readdirSync(rootDirectory).map((d) => { + d = path.join(rootDirectory, d); + return {path: d, birth: fs.statSync(d).mtime}; + }); + + directories.sort((a: KeyValue, b: KeyValue) => b.birth - a.birth); + directories = directories.slice(10, directories.length); + directories.forEach((dir) => { + this.debug(`Removing old log directory '${dir.path}'`); + rimrafSync(dir.path); + }); + } } -} -// Workaround for https://github.com/winstonjs/winston/issues/1629. -// https://github.com/Koenkk/zigbee2mqtt/pull/10905 -/* istanbul ignore next */ -async function end(): Promise { - logger.end(); - - await new Promise((resolve) => { - if (!fileTransport) { - process.nextTick(resolve); - } else { - // @ts-ignore - if (fileTransport._dest) { - // @ts-ignore - fileTransport._dest.on('finish', resolve); + // Workaround for https://github.com/winstonjs/winston/issues/1629. + // https://github.com/Koenkk/zigbee2mqtt/pull/10905 + /* istanbul ignore next */ + public async end(): Promise { + this.logger.end(); + + await new Promise((resolve) => { + if (!this.fileTransport) { + process.nextTick(resolve); } else { - // @ts-ignore - fileTransport.on('open', () => fileTransport._dest.on('finish', resolve)); + // @ts-expect-error workaround + if (this.fileTransport._dest) { + // @ts-expect-error workaround + this.fileTransport._dest.on('finish', resolve); + } else { + // @ts-expect-error workaround + this.fileTransport.on('open', () => this.fileTransport._dest.on('finish', resolve)); + } } - } - }); + }); + } } -export default { - init, logOutput, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end, removeTransport, - winston: (): winston.Logger => logger, -}; +export default new Logger(); diff --git a/test/logger.test.js b/test/logger.test.js index 213549c0c8..e7eae16b3c 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -25,16 +25,12 @@ describe('Logger', () => { it('Create log directory', () => { const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); const dirs = fs.readdirSync(dir.name); expect(dirs.length).toBe(1); }); it('Should cleanup', () => { const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); for (const d of fs.readdirSync(dir.name)) { rimrafSync(path.join(dir.name, d)); @@ -51,8 +47,6 @@ describe('Logger', () => { it('Should not cleanup when there is no timestamp set', () => { const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); for (let i = 30; i < 40; i++) { fs.mkdirSync(path.join(dir.name, `log_${i}`)); } @@ -65,16 +59,14 @@ describe('Logger', () => { it('Set and get log level', () => { const logger = require('../lib/util/logger').default; - logger.init(); - 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'); + expect(logger.getLevel()).toBe('warn');// match old Z2M levels logger.setLevel('warn'); - expect(logger.getLevel()).toBe('warning'); + expect(logger.getLevel()).toBe('warn');// match old Z2M levels logger.setLevel('error'); expect(logger.getLevel()).toBe('error'); }); @@ -83,9 +75,7 @@ describe('Logger', () => { settings.set(['advanced', 'log_level'], 'warn'); settings.reRead(); const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - expect(logger.getLevel()).toBe('warning'); + expect(logger.level).toBe('warning');// getLevel() reports old Z2M level to match display/value settings.set(['advanced', 'log_level'], 'info'); settings.reRead(); }); @@ -97,20 +87,18 @@ describe('Logger', () => { } const logger = require('../lib/util/logger').default; - logger.init(); - expect(logger.winston().transports.length).toBe(2); + expect(logger.winston.transports.length).toBe(2); const transport = new DummyTransport(); logger.addTransport(transport); - expect(logger.winston().transports.length).toBe(3); + expect(logger.winston.transports.length).toBe(3); logger.removeTransport(transport); - expect(logger.winston().transports.length).toBe(2); + expect(logger.winston.transports.length).toBe(2); }); it('Logger should be console and file by default', () => { const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - const pipes = logger.winston()._readableState.pipes; + const pipes = logger.winston._readableState.pipes; + console.log(pipes); expect(pipes.length).toBe(2); expect(pipes[0].constructor.name).toBe('Console'); expect(pipes[0].silent).toBe(false); @@ -121,9 +109,7 @@ describe('Logger', () => { it('Logger can be file only', () => { settings.set(['advanced', 'log_output'], ['file']); const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - const pipes = logger.winston()._readableState.pipes; + const pipes = logger.winston._readableState.pipes; expect(pipes.length).toBe(2); expect(pipes[0].constructor.name).toBe('Console'); expect(pipes[0].silent).toBe(true); @@ -134,9 +120,7 @@ describe('Logger', () => { it('Logger can be console only', () => { settings.set(['advanced', 'log_output'], ['console']); const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - const pipes = logger.winston()._readableState.pipes; + const pipes = logger.winston._readableState.pipes; expect(pipes.constructor.name).toBe('Console'); expect(pipes.silent).toBe(false); }); @@ -144,9 +128,7 @@ describe('Logger', () => { it('Logger can be nothing', () => { settings.set(['advanced', 'log_output'], []); const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - const pipes = logger.winston()._readableState.pipes; + const pipes = logger.winston._readableState.pipes; expect(pipes.constructor.name).toBe('Console'); expect(pipes.silent).toBe(true); }); @@ -154,9 +136,7 @@ describe('Logger', () => { it('Should allow to disable log rotation', () => { settings.set(['advanced', 'log_rotation'], false); const logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); - const pipes = logger.winston()._readableState.pipes; + const pipes = logger.winston._readableState.pipes; expect(pipes[1].constructor.name).toBe('File'); expect(pipes[1].maxFiles).toBeNull(); expect(pipes[1].tailable).toBeFalsy(); @@ -166,8 +146,6 @@ describe('Logger', () => { it('Should allow to symlink logs to current directory', () => { settings.set(['advanced', 'log_symlink_current'], true); let logger = require('../lib/util/logger').default; - logger.init(); - logger.logOutput(); expect(fs.readdirSync(dir.name).includes('current')).toBeTruthy() jest.resetModules(); @@ -176,25 +154,24 @@ describe('Logger', () => { it('Log', () => { const logger = require('../lib/util/logger').default; - logger.init(); logger.setLevel('debug'); - const debug = jest.spyOn(logger.winston(), 'debug'); + const debug = jest.spyOn(logger.winston, 'debug'); logger.debug('debug'); expect(debug).toHaveBeenCalledWith('debug', {namespace: 'z2m'}); expect(debug).toHaveBeenCalledTimes(1); - const info = jest.spyOn(logger.winston(), 'info'); + const info = jest.spyOn(logger.winston, 'info'); logger.info('info'); expect(info).toHaveBeenCalledWith('info', {namespace: 'z2m'}); expect(info).toHaveBeenCalledTimes(1); - const warning = jest.spyOn(logger.winston(), 'warning'); + 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'); + const error = jest.spyOn(logger.winston, 'error'); logger.error('error'); expect(error).toHaveBeenCalledWith('error', {namespace: 'z2m'});