From adbd3691af0a1fb86bb2b9839f4f0277911f27ce Mon Sep 17 00:00:00 2001 From: peteriman Date: Sat, 1 Jan 2022 00:09:21 +0800 Subject: [PATCH 1/6] Added automated testing for file descriptor leak --- test/tap/file-descriptor-leak-test.js | 84 +++++++++++++++++++++++++++ 1 file changed, 84 insertions(+) create mode 100644 test/tap/file-descriptor-leak-test.js diff --git a/test/tap/file-descriptor-leak-test.js b/test/tap/file-descriptor-leak-test.js new file mode 100644 index 00000000..0a20fa54 --- /dev/null +++ b/test/tap/file-descriptor-leak-test.js @@ -0,0 +1,84 @@ +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 => { + return 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(); + }, 1000); + }); + + 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(); + }, 1000); + }); + + 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(); + }, 1000); + }); + + batch.teardown(async () => { + log4js.shutdown(); + + const filenames = Object.values(config.appenders).map(appender => { + return appender.filename; + }); + await removeFiles(filenames); + }); + + batch.end(); + }); + +} \ No newline at end of file From 1e066b9bfab007c89375d39224398949a381cd19 Mon Sep 17 00:00:00 2001 From: peteriman Date: Sat, 1 Jan 2022 00:14:26 +0800 Subject: [PATCH 2/6] Patched file descriptor leak by: - subsequent log4js.configure() will run log4js.shutdown() first - log4js.shutdown() will always clear/reset existing appenders and categories --- lib/appenders/index.js | 6 +++++- lib/categories.js | 7 ++++++- lib/log4js.js | 13 ++++++++++++- 3 files changed, 23 insertions(+), 3 deletions(-) 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..6bb4d8bf 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) => { @@ -205,4 +209,5 @@ module.exports = { setLevelForCategory, getEnableCallStackForCategory, setEnableCallStackForCategory, + init, }; diff --git a/lib/log4js.js b/lib/log4js.js index fdd48c84..36cd4891 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,8 +92,14 @@ 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 From 44bf7ce5bb58580822dde1ba7d2f51467849fefe Mon Sep 17 00:00:00 2001 From: peteriman Date: Sat, 1 Jan 2022 00:29:25 +0800 Subject: [PATCH 3/6] Improved code readability for shutdown() function --- lib/log4js.js | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/lib/log4js.js b/lib/log4js.js index 36cd4891..b399816c 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -104,9 +104,13 @@ function shutdown(cb) { (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; @@ -119,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; From 23330546a96803cc2a20e0ea38edecc87dd48cad Mon Sep 17 00:00:00 2001 From: peteriman Date: Mon, 17 Jan 2022 10:06:35 +0800 Subject: [PATCH 4/6] Added automated test to assert appenders and categories are reverted back to initial state on log4js.shutdown() --- lib/categories.js | 5 +++-- test/tap/logging-test.js | 46 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 49 insertions(+), 2 deletions(-) diff --git a/lib/categories.js b/lib/categories.js index 6bb4d8bf..4e559180 100644 --- a/lib/categories.js +++ b/lib/categories.js @@ -203,11 +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/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({ From c12ac23e0793c8176689306f770c6ada86290076 Mon Sep 17 00:00:00 2001 From: peteriman Date: Mon, 17 Jan 2022 10:44:55 +0800 Subject: [PATCH 5/6] Fixed ESLint arrow-body-style error --- test/tap/file-descriptor-leak-test.js | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/test/tap/file-descriptor-leak-test.js b/test/tap/file-descriptor-leak-test.js index 0a20fa54..8d475b67 100644 --- a/test/tap/file-descriptor-leak-test.js +++ b/test/tap/file-descriptor-leak-test.js @@ -6,9 +6,7 @@ const log4js = require("../../lib/log4js"); const removeFiles = async filenames => { if (!Array.isArray(filenames)) filenames = [filenames]; - const promises = filenames.map(filename => { - return fs.promises.unlink(filename); - }); + const promises = filenames.map(filename => fs.promises.unlink(filename)); await Promise.allSettled(promises); }; @@ -72,9 +70,7 @@ if (process.platform !== "win32") { batch.teardown(async () => { log4js.shutdown(); - const filenames = Object.values(config.appenders).map(appender => { - return appender.filename; - }); + const filenames = Object.values(config.appenders).map(appender => appender.filename); await removeFiles(filenames); }); From 96f198b920f80c79a929e81ca78b10c0b843a7a0 Mon Sep 17 00:00:00 2001 From: peteriman Date: Tue, 18 Jan 2022 01:13:28 +0800 Subject: [PATCH 6/6] Reduced setTimeout(1000) -> setTimeout(250) for waiting for file system to catch up --- test/tap/file-descriptor-leak-test.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/tap/file-descriptor-leak-test.js b/test/tap/file-descriptor-leak-test.js index 8d475b67..7436a8e7 100644 --- a/test/tap/file-descriptor-leak-test.js +++ b/test/tap/file-descriptor-leak-test.js @@ -40,7 +40,7 @@ if (process.platform !== "win32") { t.equal(loadedFd, initialFd + numOfAppenders, `file descriptor count should increase by ${numOfAppenders} after 1st configure() call`); t.end(); - }, 1000); + }, 250); }); batch.test("repeated log4js configure to not increase file descriptor count", t => { @@ -53,7 +53,7 @@ if (process.platform !== "win32") { t.equal(fs.readdirSync('/proc/self/fd').length, loadedFd, `file descriptor count should be identical after repeated configure() calls`); t.end(); - }, 1000); + }, 250); }); batch.test("file descriptor count should return back to initial count", t => { @@ -64,7 +64,7 @@ if (process.platform !== "win32") { t.equal(fs.readdirSync('/proc/self/fd').length, initialFd, `file descriptor count should be back to initial`); t.end(); - }, 1000); + }, 250); }); batch.teardown(async () => {