From 68035a1256f5ace2cd5e678a34493f1fa7e87f27 Mon Sep 17 00:00:00 2001 From: Koen Kanters Date: Sun, 29 May 2022 10:15:47 +0200 Subject: [PATCH] Fix restart not working (#12629) --- index.js | 13 ++- lib/controller.ts | 13 +-- lib/util/logger.ts | 186 +++++++++++++++++++++------------------- test/controller.test.js | 12 +-- test/logger.test.js | 39 ++++++--- test/stub/logger.js | 1 + 6 files changed, 144 insertions(+), 120 deletions(-) diff --git a/index.js b/index.js index cd0df2f9..c4256f10 100644 --- a/index.js +++ b/index.js @@ -2,7 +2,6 @@ require('core-js/features/object/from-entries'); require('core-js/features/array/flat'); const semver = require('semver'); const engines = require('./package.json').engines; -const indexJsRestart = 'indexjs.restart'; const fs = require('fs'); const os = require('os'); const path = require('path'); @@ -16,12 +15,12 @@ let stopping = false; const hashFile = path.join(__dirname, 'dist', '.hash'); async function restart() { - await stop(indexJsRestart); + await stop(true); await start(); } -async function exit(code, reason) { - if (reason !== indexJsRestart) { +async function exit(code, restart) { + if (!restart) { process.exit(code); } } @@ -110,14 +109,14 @@ async function start() { await controller.start(); } -async function stop(reason=null) { - await controller.stop(reason); +async function stop(restart) { + await controller.stop(restart); } async function handleQuit() { if (!stopping && controller) { stopping = true; - await stop(); + await stop(false); } } diff --git a/lib/controller.ts b/lib/controller.ts index 24e9050d..801b4f87 100644 --- a/lib/controller.ts +++ b/lib/controller.ts @@ -45,11 +45,12 @@ class Controller { private state: State; private mqtt: MQTT; private restartCallback: () => void; - private exitCallback: (code: number) => void; + private exitCallback: (code: number, restart: boolean) => void; private extensions: Extension[]; private extensionArgs: ExtensionArgs; constructor(restartCallback: () => void, exitCallback: (code: number) => void) { + logger.init(); this.eventBus = new EventBus( /* istanbul ignore next */ (error) => { logger.error(`Error: ${error.message}`); logger.debug(error.stack); @@ -186,7 +187,7 @@ class Controller { await this.callExtensions('start', [extension]); } - async stop(): Promise { + async stop(restart = false): Promise { // Call extensions await this.callExtensions('stop', this.extensions); this.eventBus.removeListeners(this); @@ -198,16 +199,16 @@ class Controller { try { await this.zigbee.stop(); logger.info('Stopped Zigbee2MQTT'); - await this.exit(0); + await this.exit(0, restart); } catch (error) { logger.error('Failed to stop Zigbee2MQTT'); - await this.exit(1); + await this.exit(1, restart); } } - async exit(code: number): Promise { + async exit(code: number, restart = false): Promise { await logger.end(); - this.exitCallback(code); + this.exitCallback(code, restart); } @bind async onZigbeeAdapterDisconnected(): Promise { diff --git a/lib/util/logger.ts b/lib/util/logger.ts index 7723d24f..62b8a1ad 100644 --- a/lib/util/logger.ts +++ b/lib/util/logger.ts @@ -9,40 +9,12 @@ import assert from 'assert'; const colorizer = winston.format.colorize(); -// What transports to enable -const output = settings.get().advanced.log_output; - -// Directory to log to -const timestamp = moment(Date.now()).format('YYYY-MM-DD.HH-mm-ss'); -const directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', timestamp); -const logFilename = settings.get().advanced.log_file.replace('%TIMESTAMP%', timestamp); - -// Make sure that log directoy exsists when not logging to stdout only -if (output.includes('file')) { - fx.mkdirSync(directory); - - if (settings.get().advanced.log_symlink_current) { - const current = settings.get().advanced.log_directory.replace('%TIMESTAMP%', 'current'); - const actual = './' + timestamp; - if (fs.existsSync(current)) { - fs.unlinkSync(current); - } - fs.symlinkSync(actual, current); - } -} - 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; -// Determine the log level. -const z2mLevel = settings.get().advanced.log_level; -const validLevels = ['info', 'error', 'warn', 'debug']; -assert(validLevels.includes(z2mLevel), `'${z2mLevel}' is not valid log_level, use one of '${validLevels.join(', ')}'`); -const level = z2mToWinstonLevel(z2mLevel); - const levelWithCompensatedLength: {[s: string]: string} = { 'info': 'info ', 'error': 'error', @@ -50,76 +22,113 @@ const levelWithCompensatedLength: {[s: string]: string} = { 'debug': 'debug', }; -const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format); +let logger: winston.Logger; +let fileTransport : winston.transport; +let output: string[]; +let directory: string; +let logFilename: string; +let transportsToUse: winston.transport[]; -// Setup default console logger -const transportsToUse: winston.transport[] = [ - new winston.transports.Console({ +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); + + // Make sure that log directoy exsists when not logging to stdout only + if (output.includes('file')) { + 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); + } + fs.symlinkSync(actual, current); + } + } + + // Determine the log level. + const z2mLevel = settings.get().advanced.log_level; + const validLevels = ['info', 'error', 'warn', 'debug']; + assert(validLevels.includes(z2mLevel), + `'${z2mLevel}' is not valid log_level, use one of '${validLevels.join(', ')}'`); + 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.combine( + 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, - silent: !output.includes('console'), 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); - - const plainPrefix = `Zigbee2MQTT:${levelWithCompensatedLength[l]}`; - let prefix = plainPrefix; - if (process.stdout.isTTY) { - prefix = colorizer.colorize(l, plainPrefix); - } - return `${prefix} ${timestamp.split('.')[0]}: ${message}`; + return `${levelWithCompensatedLength[l]} ${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) { - transportFileOptions.tailable = true; - transportFileOptions.maxFiles = 3; // Keep last 3 files - transportFileOptions.maxsize = 10000000; // 10MB -} - -let fileTransport : winston.transport; -if (output.includes('file')) { - fileTransport = new winston.transports.File(transportFileOptions); - transportsToUse.push(fileTransport); -} - -/* 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.message}`; - }), - ...settings.get().advanced.log_syslog, }; - if (options.hasOwnProperty('type')) options.type = options.type.toString(); - // @ts-ignore - transportsToUse.push(new winston.transports.Syslog(options)); -} -// Create logger -const logger = winston.createLogger({transports: transportsToUse, levels: winston.config.syslog.levels}); + if (settings.get().advanced.log_rotation) { + transportFileOptions.tailable = true; + transportFileOptions.maxFiles = 3; // Keep last 3 files + transportFileOptions.maxsize = 10000000; // 10MB + } + + if (output.includes('file')) { + fileTransport = new winston.transports.File(transportFileOptions); + transportsToUse.push(fileTransport); + } + + /* 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.message}`; + }), + ...settings.get().advanced.log_syslog, + }; + if (options.hasOwnProperty('type')) options.type = options.type.toString(); + // @ts-ignore + transportsToUse.push(new winston.transports.Syslog(options)); + } + + logger = winston.createLogger({transports: transportsToUse, levels: winston.config.syslog.levels}); +} // Cleanup any old log directory. function cleanup(): void { @@ -211,5 +220,6 @@ async function end(): Promise { } export default { - logOutput, warn, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end, winston: logger, + init, logOutput, warn, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end, + winston: (): winston.Logger => logger, }; diff --git a/test/controller.test.js b/test/controller.test.js index ec7dc54c..4fcff870 100644 --- a/test/controller.test.js +++ b/test/controller.test.js @@ -203,7 +203,7 @@ describe('Controller', () => { await flushPromises(); expect(logger.error).toHaveBeenCalledWith('MQTT failed to connect: addr not found'); expect(mockExit).toHaveBeenCalledTimes(1); - expect(mockExit).toHaveBeenCalledWith(1); + expect(mockExit).toHaveBeenCalledWith(1, false); }); it('Start controller with permit join true', async () => { @@ -220,13 +220,13 @@ describe('Controller', () => { expect(zigbeeHerdsman.setTransmitPower).toHaveBeenCalledWith(14); }); - it('Start controller and stop', async () => { + it('Start controller and stop with restart', async () => { await controller.start(); - await controller.stop(); + await controller.stop(true); expect(MQTT.end).toHaveBeenCalledTimes(1); expect(zigbeeHerdsman.stop).toHaveBeenCalledTimes(1); expect(mockExit).toHaveBeenCalledTimes(1); - expect(mockExit).toHaveBeenCalledWith(0); + expect(mockExit).toHaveBeenCalledWith(0, true); }); it('Start controller and stop', async () => { @@ -236,7 +236,7 @@ describe('Controller', () => { expect(MQTT.end).toHaveBeenCalledTimes(1); expect(zigbeeHerdsman.stop).toHaveBeenCalledTimes(1); expect(mockExit).toHaveBeenCalledTimes(1); - expect(mockExit).toHaveBeenCalledWith(1); + expect(mockExit).toHaveBeenCalledWith(1, false); }); it('Start controller adapter disconnects', async () => { @@ -247,7 +247,7 @@ describe('Controller', () => { expect(MQTT.end).toHaveBeenCalledTimes(1); expect(zigbeeHerdsman.stop).toHaveBeenCalledTimes(1); expect(mockExit).toHaveBeenCalledTimes(1); - expect(mockExit).toHaveBeenCalledWith(1); + expect(mockExit).toHaveBeenCalledWith(1, false); }); it('Handle mqtt message', async () => { diff --git a/test/logger.test.js b/test/logger.test.js index 5c9e1cb4..7514cd53 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -25,6 +25,7 @@ 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); @@ -32,6 +33,7 @@ describe('Logger', () => { it('Should cleanup', () => { const logger = require('../lib/util/logger').default; + logger.init(); logger.logOutput(); for (const d of fs.readdirSync(dir.name)) { @@ -49,6 +51,7 @@ 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}`)); @@ -62,6 +65,7 @@ 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'); @@ -74,23 +78,26 @@ describe('Logger', () => { } const logger = require('../lib/util/logger').default; - expect(logger.winston.transports.length).toBe(2); + logger.init(); + expect(logger.winston().transports.length).toBe(2); logger.addTransport(new DummyTransport()); - expect(logger.winston.transports.length).toBe(3); + 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.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(); 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(false); @@ -101,8 +108,9 @@ 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); @@ -113,8 +121,9 @@ 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); }); @@ -122,8 +131,9 @@ 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); }); @@ -131,8 +141,9 @@ 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(); @@ -142,6 +153,7 @@ 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() @@ -151,23 +163,24 @@ describe('Logger', () => { it('Log', () => { const logger = require('../lib/util/logger').default; - const warn = jest.spyOn(logger.winston, 'warning'); + logger.init(); + const warn = jest.spyOn(logger.winston(), 'warning'); logger.warn('warn'); expect(warn).toHaveBeenCalledWith('warn'); - const debug = jest.spyOn(logger.winston, 'debug'); + const debug = jest.spyOn(logger.winston(), 'debug'); logger.debug('debug'); expect(debug).toHaveBeenCalledWith('debug'); - const warning = jest.spyOn(logger.winston, 'warning'); + const warning = jest.spyOn(logger.winston(), 'warning'); logger.warning('warning'); expect(warning).toHaveBeenCalledWith('warning'); - const info = jest.spyOn(logger.winston, 'info'); + const info = jest.spyOn(logger.winston(), 'info'); logger.info('info'); expect(info).toHaveBeenCalledWith('info'); - const error = jest.spyOn(logger.winston, 'error'); + const error = jest.spyOn(logger.winston(), 'error'); logger.error('error'); expect(error).toHaveBeenCalledWith('error'); }); diff --git a/test/stub/logger.js b/test/stub/logger.js index 7fabca4c..bfafb5f5 100644 --- a/test/stub/logger.js +++ b/test/stub/logger.js @@ -12,6 +12,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)), error: jest.fn().mockImplementation((msg) => callTransports('error', msg)),