From a0b47d020172479b2e8149bbfadb424b828238ee Mon Sep 17 00:00:00 2001 From: burgerni10 Date: Fri, 25 Nov 2022 15:48:08 +0100 Subject: [PATCH] fix(logs): roll files and remove the oldest file periodically --- src/index.js | 11 +- src/service/logger/file-cleanup.service.js | 98 +++++++++++++++++ .../logger/file-cleanup.service.spec.js | 103 ++++++++++++++++++ src/service/logger/logger.service.js | 19 +++- src/service/logger/logger.service.spec.js | 1 + 5 files changed, 227 insertions(+), 5 deletions(-) create mode 100644 src/service/logger/file-cleanup.service.js create mode 100644 src/service/logger/file-cleanup.service.spec.js diff --git a/src/index.js b/src/index.js index ccfea05d8c..27c51eecb9 100644 --- a/src/index.js +++ b/src/index.js @@ -31,9 +31,9 @@ const { } = getCommandLineArguments() const logParameters = { - consoleLog: { level: 'debug' }, + consoleLog: { level: 'trace' }, fileLog: { - level: 'debug', + level: 'trace', fileName: path.resolve(path.parse(configFile).dir, LOG_FOLDER_NAME, MAIN_LOG_FILE_NAME), maxSize: 10, numberOfFiles: 5, @@ -94,6 +94,7 @@ if (cluster.isMaster) { }) break case 'shutdown-ready': + loggerService.stop() process.exit() break default: @@ -159,6 +160,8 @@ if (cluster.isMaster) { Promise.allSettled(stopAll).then(() => { process.exit() }) + loggerService.stop() + oibusLoggerService.stop() }) // Receive messages from the master process. @@ -170,6 +173,9 @@ if (cluster.isMaster) { await oibusEngine.stop() await historyQueryEngine.stop() await server.stop() + + // Restart the logger to update its settings + oibusLoggerService.stop() const { engineConfig: newEngineConfig } = configService.getConfig() await oibusLoggerService.start(newEngineConfig.name, newEngineConfig.logParameters) @@ -186,6 +192,7 @@ if (cluster.isMaster) { break case 'reload': forkLogger.info('Reloading OIBus') + oibusLoggerService.stop() Promise.allSettled([oibusEngine.stop(), historyQueryEngine.stop(), server.stop()]).then(() => { process.exit() }) diff --git a/src/service/logger/file-cleanup.service.js b/src/service/logger/file-cleanup.service.js new file mode 100644 index 0000000000..d692ce5d05 --- /dev/null +++ b/src/service/logger/file-cleanup.service.js @@ -0,0 +1,98 @@ +const path = require('node:path') +const fs = require('node:fs/promises') + +const CLEAN_UP_INTERVAL = 24 * 3600 * 1000 // One day + +/** + * Service used to clean up log files rolled by the pino-roll library + * This service should be removed if pino-roll implements this feature one day + */ +class FileCleanupService { + /** + * @param {String} logFolder - The path of the log folder + * @param {Logger} logger - The logger + * @param {String} filename - The filename pattern + * @param {Number} numberOfFiles - The number of files to keep + */ + constructor( + logFolder, + logger, + filename, + numberOfFiles, + ) { + this.logFolder = path.resolve(logFolder) + this.logger = logger + this.filename = filename + this.numberOfFiles = numberOfFiles + this.cleanUpInterval = null + } + + /** + * Clean up the folder at start and then every CLEAN_UP_INTERVAL ms + * @return {void} + */ + async start() { + await this.cleanUpLogFiles() + this.cleanUpInterval = setInterval(this.cleanUpLogFiles.bind(this), CLEAN_UP_INTERVAL) + } + + /** + * Clear the interval when OIBus stop + * @return {void} + */ + stop() { + this.logger.trace('Stopping file cleanup service.') + clearInterval(this.cleanUpInterval) + } + + /** + * List the files of the log folder and remove the older files if the number of files is over the limit of files + * @return {Promise} - The result promise + */ + async cleanUpLogFiles() { + try { + const filenames = await fs.readdir(this.logFolder) + + const regexp = new RegExp(`^${this.filename}\\.[0-9]*$`) + const fileList = [] + const logFiles = filenames.filter((file) => file.match(regexp)) + + this.logger.trace(`Found ${logFiles.length} log files with RegExp ${regexp} in folder "${this.logFolder}".`) + if (logFiles.length > this.numberOfFiles) { + await logFiles.reduce((promise, filename) => promise.then( + async () => { + try { + const fileStat = await fs.stat(path.resolve(this.logFolder, filename)) + fileList.push({ file: path.resolve(this.logFolder, filename), modifiedTime: fileStat.mtimeMs }) + } catch (error) { + // If a file is being written or corrupted, the stat method can fail + // An error is logged and the cache goes through the other files + this.logger.error(`Error while reading log file "${path.resolve(this.logFolder, filename)}": ${error}`) + } + }, + ), Promise.resolve()) + + // Sort the newest files first and keep the numberOfFiles first files (the other files will be removed + const fileToRemove = fileList.sort((a, b) => a.modifiedTime - b.modifiedTime) + .map((element) => element.file) + .slice(0, fileList.length - this.numberOfFiles) + this.logger.trace(`Removing ${fileToRemove.length} log files.`) + await fileToRemove.reduce((promise, filename) => promise.then( + async () => { + try { + await fs.unlink(path.resolve(this.logFolder, filename)) + } catch (error) { + // If a file is being written or corrupted, the stat method can fail + // An error is logged and the cache goes through the other files + this.logger.error(`Error while removing log file "${path.resolve(this.logFolder, filename)}": ${error}`) + } + }, + ), Promise.resolve()) + } + } catch (error) { + this.logger.error(error) + } + } +} + +module.exports = FileCleanupService diff --git a/src/service/logger/file-cleanup.service.spec.js b/src/service/logger/file-cleanup.service.spec.js new file mode 100644 index 0000000000..923542fc9f --- /dev/null +++ b/src/service/logger/file-cleanup.service.spec.js @@ -0,0 +1,103 @@ +const fs = require('node:fs/promises') +const path = require('node:path') +const FileCleanupService = require('./file-cleanup.service') + +jest.mock('node:fs/promises') + +// mock EncryptionService +let fileCleanupService = null + +// Mock logger +const logger = { + error: jest.fn(), + warn: jest.fn(), + info: jest.fn(), + debug: jest.fn(), + trace: jest.fn(), +} + +describe('FileCleanupService', () => { + beforeEach(() => { + jest.resetAllMocks() + jest.useFakeTimers() + fileCleanupService = new FileCleanupService('logFolder', logger, 'journal.log', 2) + }) + + it('should properly start', async () => { + fileCleanupService.cleanUpLogFiles = jest.fn() + + await fileCleanupService.start() + expect(fileCleanupService.cleanUpLogFiles).toHaveBeenCalledTimes(1) + jest.advanceTimersByTime(12 * 3600 * 1000) // Advance by half a day + expect(fileCleanupService.cleanUpLogFiles).toHaveBeenCalledTimes(1) + jest.advanceTimersByTime(12 * 3600 * 1000) // Advance by half a day + expect(fileCleanupService.cleanUpLogFiles).toHaveBeenCalledTimes(2) + }) + + it('should properly stop', () => { + const clearIntervalSpy = jest.spyOn(global, 'clearInterval') + + fileCleanupService.stop() + expect(logger.trace).toHaveBeenCalledWith('Stopping file cleanup service.') + expect(clearIntervalSpy).toHaveBeenCalledTimes(1) + }) + + it('should properly clear up folder', async () => { + fs.readdir.mockImplementation(() => [ + 'journal.log.1', + 'journal.log.2', + 'journal.log.233', + 'journal.log.0.backup', + 'journal.db', + 'migration-journal.log', + ]) + + fs.stat.mockImplementationOnce(() => ({ mtimeMs: 2 })) + .mockImplementationOnce(() => ({ mtimeMs: 1 })) + .mockImplementationOnce(() => ({ mtimeMs: 5 })) + + await fileCleanupService.cleanUpLogFiles() + expect(fs.readdir).toHaveBeenCalledWith(path.resolve('logFolder')) + expect(logger.trace).toHaveBeenCalledWith('Found 3 log files with RegExp /^journal.log\\.[0-9]*$/ ' + + `in folder "${path.resolve('logFolder')}".`) + expect(logger.trace).toHaveBeenCalledWith('Removing 1 log files.') + expect(fs.unlink).toHaveBeenCalledWith(path.resolve('logFolder', 'journal.log.2')) + }) + + it('should properly manage file access errors', async () => { + fs.readdir.mockImplementation(() => [ + 'journal.log.1', + 'journal.log.2', + 'journal.log.233', + 'journal.log.3', + 'journal.log.4', + 'journal.log.0.backup', + 'journal.db', + 'migration-journal.log', + ]) + + fs.stat.mockImplementationOnce(() => ({ mtimeMs: 2 })) + .mockImplementationOnce(() => ({ mtimeMs: 1 })) + .mockImplementationOnce(() => ({ mtimeMs: 5 })) + .mockImplementationOnce(() => { + throw new Error('stat error') + }) + .mockImplementationOnce(() => ({ mtimeMs: 9 })) + + fs.unlink.mockImplementationOnce(() => true) + .mockImplementationOnce(() => { + throw new Error('unlink error') + }) + await fileCleanupService.cleanUpLogFiles() + expect(fs.readdir).toHaveBeenCalledWith(path.resolve('logFolder')) + expect(logger.trace).toHaveBeenCalledWith('Found 5 log files with RegExp /^journal.log\\.[0-9]*$/ ' + + `in folder "${path.resolve('logFolder')}".`) + + expect(logger.error).toHaveBeenCalledWith('Error while reading log file ' + + `"${path.resolve('logFolder', 'journal.log.3')}": ${new Error('stat error')}`) + expect(logger.trace).toHaveBeenCalledWith('Removing 2 log files.') + expect(fs.unlink).toHaveBeenCalledWith(path.resolve('logFolder', 'journal.log.2')) + expect(logger.error).toHaveBeenCalledWith('Error while removing log file ' + + `"${path.resolve('logFolder', 'journal.log.1')}": ${new Error('unlink error')}`) + }) +}) diff --git a/src/service/logger/logger.service.js b/src/service/logger/logger.service.js index 3503e1ddaf..aca2f48efa 100644 --- a/src/service/logger/logger.service.js +++ b/src/service/logger/logger.service.js @@ -1,6 +1,7 @@ const path = require('node:path') const pino = require('pino') +const FileCleanupService = require('./file-cleanup.service') const LOG_FOLDER_NAME = 'logs' const LOG_FILE_NAME = 'journal.log' @@ -22,9 +23,10 @@ class LoggerService { * @param {String} scope - Gives the scope of the logger (the engine, the connector...) */ constructor(scope = 'main') { + this.scope = scope this.logger = null this.encryptionService = null - this.scope = scope + this.fileCleanUpService = null } /** @@ -48,11 +50,11 @@ class LoggerService { const { consoleLog, fileLog, sqliteLog, lokiLog } = logParameters targets.push({ target: 'pino-pretty', options: { colorize: true, singleLine: true }, level: consoleLog.level }) - const filename = fileLog.fileName ? fileLog.fileName : path.resolve(LOG_FOLDER_NAME, LOG_FILE_NAME) + const filePath = fileLog.fileName ? fileLog.fileName : path.resolve(LOG_FOLDER_NAME, LOG_FILE_NAME) targets.push({ target: 'pino-roll', options: { - file: filename, + file: filePath, size: fileLog.maxSize, }, level: fileLog.level, @@ -99,6 +101,9 @@ class LoggerService { timestamp: pino.stdTimeFunctions.isoTime, transport: { targets }, }) + + this.fileCleanUpService = new FileCleanupService(path.parse(filePath).dir, this.logger, path.parse(filePath).base, fileLog.numberOfFiles) + await this.fileCleanUpService.start() } createChildLogger(scope) { @@ -130,6 +135,14 @@ class LoggerService { Error.prepareStackTrace = oldStackTrace } } + + /** + * Stop the logger and associated services + * @return {void} + */ + stop() { + this.fileCleanUpService.stop() + } } module.exports = LoggerService diff --git a/src/service/logger/logger.service.spec.js b/src/service/logger/logger.service.spec.js index 664283d067..52eb49fe49 100644 --- a/src/service/logger/logger.service.spec.js +++ b/src/service/logger/logger.service.spec.js @@ -3,6 +3,7 @@ const path = require('node:path') const LoggerService = require('./logger.service') jest.mock('pino') +jest.mock('./file-cleanup.service') // mock EncryptionService const encryptionService = { decryptText: (textToDecipher) => textToDecipher }