Merge pull request #1113 from peteriman/Fixes-FileDescriptorLeak

Fixes file descriptor leak in certain use cases

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;

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,
+});

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;

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();
+  });
+
+}

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({