diff --git a/lib/appenders/index.js b/lib/appenders/index.js index e81f268e..7292aa3b 100644 --- a/lib/appenders/index.js +++ b/lib/appenders/index.js @@ -102,7 +102,10 @@ const setup = (config) => { }); }; -setup({ appenders: { out: { type: 'stdout' } }, categories: { default: { appenders: ['out'], level: 'trace' } } }); +const init = () => { + setup({ appenders: { out: { type: 'stdout' } }, categories: { default: { appenders: ['out'], level: 'trace' } } }); +}; +init(); configuration.addListener((config) => { configuration.throwExceptionIf( @@ -129,3 +132,4 @@ configuration.addListener((config) => { configuration.addListener(setup); module.exports = appenders; +module.exports.init = init; diff --git a/lib/categories.js b/lib/categories.js index b9bb8b1c..4e559180 100644 --- a/lib/categories.js +++ b/lib/categories.js @@ -161,7 +161,11 @@ const setup = (config) => { }); }; -setup({ categories: { default: { appenders: ['out'], level: 'OFF' } } }); +const init = () => { + setup({ categories: { default: { appenders: ['out'], level: 'OFF' } } }); +}; +init(); + configuration.addListener(setup); const configForCategory = (category) => { @@ -199,10 +203,12 @@ const setEnableCallStackForCategory = (category, useCallStack) => { configForCategory(category).enableCallStack = useCallStack; }; -module.exports = { +module.exports = categories; +module.exports = Object.assign(module.exports, { appendersForCategory, getLevelForCategory, setLevelForCategory, getEnableCallStackForCategory, setEnableCallStackForCategory, -}; + init, +}); diff --git a/lib/log4js.js b/lib/log4js.js index fdd48c84..b399816c 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -56,6 +56,11 @@ function loadConfigurationFile(filename) { } function configure(configurationFileOrObject) { + if (enabled) { + // eslint-disable-next-line no-use-before-define + shutdown(); + } + let configObject = configurationFileOrObject; if (typeof configObject === "string") { @@ -87,15 +92,25 @@ function shutdown(cb) { // not being able to be drained because of run-away log writes. enabled = false; - // Call each of the shutdown functions in parallel + // Clone out to maintain a reference const appendersToCheck = Array.from(appenders.values()); + + // Reset immediately to prevent leaks + appenders.init(); + categories.init(); + + // Call each of the shutdown functions in parallel const shutdownFunctions = appendersToCheck.reduceRight( (accum, next) => (next.shutdown ? accum + 1 : accum), 0 ); + if (shutdownFunctions === 0) { + debug("No appenders with shutdown functions found."); + return cb !== undefined && cb(); + } + let completed = 0; let error; - debug(`Found ${shutdownFunctions} appenders with shutdown functions.`); function complete(err) { error = error || err; @@ -108,12 +123,6 @@ function shutdown(cb) { } } } - - if (shutdownFunctions === 0) { - debug("No appenders with shutdown functions found."); - return cb !== undefined && cb(); - } - appendersToCheck.filter(a => a.shutdown).forEach(a => a.shutdown(complete)); return null; diff --git a/test/tap/file-descriptor-leak-test.js b/test/tap/file-descriptor-leak-test.js new file mode 100644 index 00000000..7436a8e7 --- /dev/null +++ b/test/tap/file-descriptor-leak-test.js @@ -0,0 +1,80 @@ +const { test } = require("tap"); +const fs = require("fs"); +const path = require("path"); +const log4js = require("../../lib/log4js"); + +const removeFiles = async filenames => { + if (!Array.isArray(filenames)) + filenames = [filenames]; + const promises = filenames.map(filename => fs.promises.unlink(filename)); + await Promise.allSettled(promises); +}; + +// no file descriptors on Windows, so don't run the tests +if (process.platform !== "win32") { + + test("multiple log4js configure fd leak test", batch => { + const config = { + appenders: {}, + categories: { + default: { appenders: [], level: 'debug' } + } + }; + + // create 11 appenders + const numOfAppenders = 11; + for (let i = 1; i <= numOfAppenders; i++) { + config.appenders[`app${i}`] = { type: 'file', filename: path.join(__dirname, `file${i}.log`) }; + config.categories.default.appenders.push(`app${i}`); + } + + const initialFd = fs.readdirSync('/proc/self/fd').length; + let loadedFd; + + batch.test("initial log4js configure to increase file descriptor count", t => { + log4js.configure(config); + + // wait for the file system to catch up + setTimeout(() => { + loadedFd = fs.readdirSync('/proc/self/fd').length; + t.equal(loadedFd, initialFd + numOfAppenders, + `file descriptor count should increase by ${numOfAppenders} after 1st configure() call`); + t.end(); + }, 250); + }); + + batch.test("repeated log4js configure to not increase file descriptor count", t => { + log4js.configure(config); + log4js.configure(config); + log4js.configure(config); + + // wait for the file system to catch up + setTimeout(() => { + t.equal(fs.readdirSync('/proc/self/fd').length, loadedFd, + `file descriptor count should be identical after repeated configure() calls`); + t.end(); + }, 250); + }); + + batch.test("file descriptor count should return back to initial count", t => { + log4js.shutdown(); + + // wait for the file system to catch up + setTimeout(() => { + t.equal(fs.readdirSync('/proc/self/fd').length, initialFd, + `file descriptor count should be back to initial`); + t.end(); + }, 250); + }); + + batch.teardown(async () => { + log4js.shutdown(); + + const filenames = Object.values(config.appenders).map(appender => appender.filename); + await removeFiles(filenames); + }); + + batch.end(); + }); + +} \ No newline at end of file diff --git a/test/tap/logging-test.js b/test/tap/logging-test.js index be12436b..be39e7f5 100644 --- a/test/tap/logging-test.js +++ b/test/tap/logging-test.js @@ -4,6 +4,52 @@ const util = require("util"); const recording = require("../../lib/appenders/recording"); test("log4js", batch => { + batch.test("shutdown should return appenders and categories back to initial state", t => { + const stringifyMap = (map) => JSON.stringify(Array.from(map)); + const deepCopyMap = (map) => new Map(JSON.parse(stringifyMap(map))); + + const log4js = require("../../lib/log4js"); + + const appenders = require("../../lib/appenders"); + const categories = require("../../lib/categories"); + const initialAppenders = deepCopyMap(appenders); + const initialCategories = deepCopyMap(categories); + + log4js.configure({ + appenders: { recorder: { type: "recording" } }, + categories: { default: { appenders: ["recorder"], level: "DEBUG" } } + }); + + const configuredAppenders = deepCopyMap(appenders); + const configuredCategories = deepCopyMap(categories); + t.notEqual( + stringifyMap(configuredAppenders), + stringifyMap(initialAppenders), + "appenders should be different from initial state" + ); + t.notEqual( + stringifyMap(configuredCategories), + stringifyMap(initialCategories), + "categories should be different from initial state" + ); + + log4js.shutdown(() => { + const finalAppenders = deepCopyMap(appenders); + const finalCategories = deepCopyMap(categories); + t.equal( + stringifyMap(finalAppenders), + stringifyMap(initialAppenders), + "appenders should revert back to initial state" + ); + t.equal( + stringifyMap(finalCategories), + stringifyMap(initialCategories), + "categories should revert back to initial state" + ); + t.end(); + }); + }); + batch.test("getLogger", t => { const log4js = require("../../lib/log4js"); log4js.configure({