Skip to content

Commit

Permalink
fix(logs): roll files and remove the oldest file periodically
Browse files Browse the repository at this point in the history
  • Loading branch information
burgerni10 authored and Nicolas Burger committed Nov 28, 2022
1 parent cc720c5 commit a0b47d0
Show file tree
Hide file tree
Showing 5 changed files with 227 additions and 5 deletions.
11 changes: 9 additions & 2 deletions src/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -94,6 +94,7 @@ if (cluster.isMaster) {
})
break
case 'shutdown-ready':
loggerService.stop()
process.exit()
break
default:
Expand Down Expand Up @@ -159,6 +160,8 @@ if (cluster.isMaster) {
Promise.allSettled(stopAll).then(() => {
process.exit()
})
loggerService.stop()
oibusLoggerService.stop()
})

// Receive messages from the master process.
Expand All @@ -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)

Expand All @@ -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()
})
Expand Down
98 changes: 98 additions & 0 deletions src/service/logger/file-cleanup.service.js
Original file line number Diff line number Diff line change
@@ -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<void>} - 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
103 changes: 103 additions & 0 deletions src/service/logger/file-cleanup.service.spec.js
Original file line number Diff line number Diff line change
@@ -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')}`)
})
})
19 changes: 16 additions & 3 deletions src/service/logger/logger.service.js
Original file line number Diff line number Diff line change
@@ -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'
Expand All @@ -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
}

/**
Expand All @@ -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,
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -130,6 +135,14 @@ class LoggerService {
Error.prepareStackTrace = oldStackTrace
}
}

/**
* Stop the logger and associated services
* @return {void}
*/
stop() {
this.fileCleanUpService.stop()
}
}

module.exports = LoggerService
1 change: 1 addition & 0 deletions src/service/logger/logger.service.spec.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 }
Expand Down

0 comments on commit a0b47d0

Please sign in to comment.