diff --git a/lib/appenders/index.js b/lib/appenders/index.js index 647ed8e..7069d9e 100644 --- a/lib/appenders/index.js +++ b/lib/appenders/index.js @@ -73,14 +73,16 @@ const createAppender = (name, config) => { `Appender ${appenderConfig.type} exports an appender function.`, "DeprecationWarning", "log4js-node-DEP0001" ); - debug(`DEPRECATION: Appender ${appenderConfig.type} exports an appender function.`); + debug("[log4js-node-DEP0001]", + `DEPRECATION: Appender ${appenderConfig.type} exports an appender function.`); } if (appenderModule.shutdown) { process.emitWarning( `Appender ${appenderConfig.type} exports a shutdown function.`, "DeprecationWarning", "log4js-node-DEP0002" ); - debug(`DEPRECATION: Appender ${appenderConfig.type} exports a shutdown function.`); + debug("[log4js-node-DEP0002]", + `DEPRECATION: Appender ${appenderConfig.type} exports a shutdown function.`); } debug(`${name}: clustering.isMaster ? ${clustering.isMaster()}`); diff --git a/lib/layouts.js b/lib/layouts.js index bdb327c..5c2d600 100644 --- a/lib/layouts.js +++ b/lib/layouts.js @@ -160,7 +160,8 @@ function patternLayout(pattern, tokens) { "Please use %d{ABSOLUTETIME} instead.", "DeprecationWarning", "log4js-node-DEP0003" ); - debug("DEPRECATION: Pattern %d{ABSOLUTE} is deprecated and replaced by %d{ABSOLUTETIME}."); + debug("[log4js-node-DEP0003]", + "DEPRECATION: Pattern %d{ABSOLUTE} is deprecated and replaced by %d{ABSOLUTETIME}."); // falls through case 'ABSOLUTETIME': case 'ABSOLUTETIME_FORMAT': @@ -172,7 +173,8 @@ function patternLayout(pattern, tokens) { "Please use %d{DATETIME} instead.", "DeprecationWarning", "log4js-node-DEP0004" ); - debug("DEPRECATION: Pattern %d{DATE} is deprecated and replaced by %d{DATETIME}."); + debug("[log4js-node-DEP0004]", + "DEPRECATION: Pattern %d{DATE} is deprecated and replaced by %d{DATETIME}."); // falls through case 'DATETIME': case 'DATETIME_FORMAT': diff --git a/test/tap/default-settings-test.js b/test/tap/default-settings-test.js index f1816aa..77359c5 100644 --- a/test/tap/default-settings-test.js +++ b/test/tap/default-settings-test.js @@ -1,48 +1,127 @@ const { test } = require("tap"); +const debug = require("debug"); const sandbox = require("@log4js-node/sandboxed-module"); -test("default settings", t => { - const output = []; +test("default settings", batch => { + const originalListener = process.listeners("warning")[process.listeners("warning").length - 1]; + const warningListener = error => { + if (error.name === "DeprecationWarning") { + if (error.code.startsWith("log4js-node-DEP0001") || error.code.startsWith("log4js-node-DEP0002")) { + return; + } + } + originalListener(error); + }; + process.off("warning", originalListener); + process.on("warning", warningListener); + const debugWasEnabled = debug.enabled("log4js:appenders"); + const debugLogs = []; + const originalWrite = process.stderr.write; + process.stderr.write = (string, encoding, fd) => { + debugLogs.push(string); + if (debugWasEnabled) { + originalWrite.apply(process.stderr, [string, encoding, fd]); + } + }; + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:appenders`); + + batch.teardown(async () => { + // next event loop so that past warnings will not be printed + setImmediate(() => { + process.off("warning", warningListener); + process.on("warning", originalListener); + }); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + + const output = []; const log4js = sandbox.require("../../lib/log4js", { requires: { "./appenders/stdout": { name: "stdout", - appender() { + appender() { // deprecated return function(evt) { output.push(evt); }; }, - shutdown() { + shutdown() { // deprecated }, configure() { return this.appender(); } - } + }, + debug } }); - const logger = log4js.getLogger("default-settings"); - logger.info("This should not be logged yet."); + let logger; - t.plan(3); - t.equal( - output.length, - 0, - "Nothing should be logged until configure is called." - ); - - log4js.configure({ - appenders: { stdout: { type: "stdout" } }, - categories: { default: { appenders: ["stdout"], level: "debug" } } + batch.test("should call configure() on getLogger() if not configured", t => { + const DEP0001 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0001") > -1).length; + const DEP0002 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0002") > -1).length; + logger = log4js.getLogger("default-settings"); + t.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0001") > -1).length, + DEP0001 + 1, + "deprecation log4js-node-DEP0001 emitted" + ); + t.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0002") > -1).length, + DEP0002 + 1, + "deprecation log4js-node-DEP0002 emitted" + ); + t.end(); }); - logger.info("This should go to stdout."); - t.equal(output.length, 1, "It should log to stdout."); - t.equal( - output[0].data[0], - "This should go to stdout.", - "It should log the message." - ); - t.end(); + batch.test("nothing should be logged until level is set or configure() is called", t => { + const originalLevel = logger.level; + t.equal( + originalLevel.levelStr, + "OFF", + "default logger.level should be OFF" + ); + + logger.info("This should not be logged yet."); + t.equal(output.length, 0, "nothing should be logged"); + + t.test("after level is set", assert => { + logger.level = "debug"; + logger.info("This should be logged."); + assert.equal(output.length, 1, "should log the message if level is set"); + assert.equal(output[output.length - 1].data[0], "This should be logged."); + logger.level = originalLevel; + assert.end(); + }); + + t.test("after configure() is called", assert => { + const DEP0001 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0001") > -1).length; + const DEP0002 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0002") > -1).length; + log4js.configure({ + appenders: { stdout: { type: "stdout" } }, + categories: { default: { appenders: ["stdout"], level: "debug" } } + }); + assert.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0001") > -1).length, + DEP0001 + 1, + "deprecation log4js-node-DEP0001 emitted" + ); + assert.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0002") > -1).length, + DEP0002 + 1, + "deprecation log4js-node-DEP0002 emitted" + ); + + logger.info("This should go to stdout."); + assert.equal(output.length, 2, "should log the message after configure() is called"); + assert.equal(output[output.length - 1].data[0], "This should go to stdout."); + assert.end(); + }); + + t.end(); + }); + + batch.end(); }); diff --git a/test/tap/file-sighup-test.js b/test/tap/file-sighup-test.js index f883e3d..deb612a 100644 --- a/test/tap/file-sighup-test.js +++ b/test/tap/file-sighup-test.js @@ -14,11 +14,15 @@ test("file appender single SIGHUP handler", t => { const initialListeners = process.listenerCount("SIGHUP"); let warning; + const originalListener = process.listeners("warning")[process.listeners("warning").length - 1]; const warningListener = error => { if (error.type === "SIGHUP" && error.name === "MaxListenersExceededWarning") { warning = error; + return; } + originalListener(error); }; + process.off("warning", originalListener); process.on("warning", warningListener); const config = { @@ -39,21 +43,25 @@ test("file appender single SIGHUP handler", t => { log4js.configure(config); t.teardown(async () => { + // next event loop so that past warnings will not be printed + setImmediate(() => { + process.off("warning", warningListener); + process.on("warning", originalListener); + }); + await new Promise(resolve => { log4js.shutdown(resolve); }); const filenames = Object.values(config.appenders).map(appender => appender.filename); await removeFiles(filenames); - - process.off("warning", warningListener); }); t.plan(2); - // put in a timeout 0 to allow event emitter/listener to happen - setTimeout(() => { + // next event loop to allow event emitter/listener to happen + setImmediate(() => { t.notOk(warning, "should not have MaxListenersExceededWarning for SIGHUP"); t.equal(process.listenerCount("SIGHUP") - initialListeners, 1, "should be 1 SIGHUP listener"); t.end(); - }, 0); + }); }); test("file appender SIGHUP", t => { diff --git a/test/tap/layouts-test.js b/test/tap/layouts-test.js index 855b6c9..713f63f 100644 --- a/test/tap/layouts-test.js +++ b/test/tap/layouts-test.js @@ -1,4 +1,5 @@ const { test } = require("tap"); +const debug = require("debug"); const os = require("os"); const path = require("path"); @@ -245,6 +246,40 @@ test("log4js layouts", batch => { }); batch.test("patternLayout", t => { + const originalListener = process.listeners("warning")[process.listeners("warning").length - 1]; + const warningListener = error => { + if (error.name === "DeprecationWarning") { + if (error.code.startsWith("log4js-node-DEP0003") || error.code.startsWith("log4js-node-DEP0004")) { + return; + } + } + originalListener(error); + }; + process.off("warning", originalListener); + process.on("warning", warningListener); + + const debugWasEnabled = debug.enabled("log4js:layouts"); + const debugLogs = []; + const originalWrite = process.stderr.write; + process.stderr.write = (string, encoding, fd) => { + debugLogs.push(string); + if (debugWasEnabled) { + originalWrite.apply(process.stderr, [string, encoding, fd]); + } + }; + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:layouts`); + + batch.teardown(async () => { + // next event loop so that past warnings will not be printed + setImmediate(() => { + process.off("warning", warningListener); + process.on("warning", originalListener); + }); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + const tokens = { testString: "testStringToken", testFunction() { @@ -421,6 +456,7 @@ test("log4js layouts", batch => { "2010-12-05T14:18:30.045+10:00" ); + const DEP0003 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0003") > -1).length; testPattern( assert, layout, @@ -429,6 +465,11 @@ test("log4js layouts", batch => { "%d{ABSOLUTE}", // deprecated "14:18:30.045" ); + assert.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0003") > -1).length, + DEP0003 + 1, + "deprecation log4js-node-DEP0003 emitted" + ); testPattern( assert, layout, @@ -438,6 +479,7 @@ test("log4js layouts", batch => { "14:18:30.045" ); + const DEP0004 = debugLogs.filter((e) => e.indexOf("log4js-node-DEP0004") > -1).length; testPattern( assert, layout, @@ -446,6 +488,11 @@ test("log4js layouts", batch => { "%d{DATE}", // deprecated "05 12 2010 14:18:30.045" ); + assert.equal( + debugLogs.filter((e) => e.indexOf("log4js-node-DEP0004") > -1).length, + DEP0004 + 1, + "deprecation log4js-node-DEP0004 emitted" + ); testPattern( assert, layout, diff --git a/test/tap/multi-file-appender-test.js b/test/tap/multi-file-appender-test.js index 1e0be19..3becca3 100644 --- a/test/tap/multi-file-appender-test.js +++ b/test/tap/multi-file-appender-test.js @@ -74,10 +74,6 @@ test("multiFile appender", batch => { ); batch.test("should close file after timeout", t => { - t.teardown(async () => { - await new Promise(resolve => { log4js.shutdown(resolve); }); - await removeFiles("logs/C.log"); - }); /* checking that the file is closed after a timeout is done by looking at the debug logs since detecting file locks with node.js is platform specific. */ @@ -90,7 +86,16 @@ test("multiFile appender", batch => { originalWrite.apply(process.stderr, [string, encoding, fd]); } }; - debug.enable("log4js:multiFile"); + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:multiFile`); + + t.teardown(async () => { + await new Promise(resolve => { log4js.shutdown(resolve); }); + await removeFiles("logs/C.log"); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + const timeoutMs = 25; log4js.configure({ appenders: { @@ -113,19 +118,11 @@ test("multiFile appender", batch => { `C not used for > ${timeoutMs} ms => close`, "(timeout1) should have closed" ); - if (!debugWasEnabled) { - debug.disable("log4js:multiFile"); - } - process.stderr.write = originalWrite; t.end(); }, timeoutMs*1 + 50); // add a 50 ms delay }); batch.test("should close file safely after timeout", t => { - t.teardown(async () => { - await new Promise(resolve => { sandboxedLog4js.shutdown(resolve); }); // eslint-disable-line no-use-before-define - await removeFiles("logs/C.log"); - }); const error = new Error("fileAppender shutdown error"); const sandboxedLog4js = sandbox.require("../../lib/log4js", { requires: { @@ -157,7 +154,16 @@ test("multiFile appender", batch => { originalWrite.apply(process.stderr, [string, encoding, fd]); } }; - debug.enable("log4js:multiFile"); + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:multiFile`); + + t.teardown(async () => { + await new Promise(resolve => { sandboxedLog4js.shutdown(resolve); }); + await removeFiles("logs/C.log"); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + const timeoutMs = 25; sandboxedLog4js.configure({ appenders: { @@ -185,19 +191,11 @@ test("multiFile appender", batch => { `ignore error on file shutdown: ${error.message}`, "safely shutdown" ); - if (!debugWasEnabled) { - debug.disable("log4js:multiFile"); - } - process.stderr.write = originalWrite; t.end(); }, timeoutMs*1 + 50); // add a 50 ms delay }); batch.test("should close file after extended timeout", t => { - t.teardown(async () => { - await new Promise(resolve => { log4js.shutdown(resolve); }); - await removeFiles("logs/D.log"); - }); /* checking that the file is closed after a timeout is done by looking at the debug logs since detecting file locks with node.js is platform specific. */ @@ -210,7 +208,16 @@ test("multiFile appender", batch => { originalWrite.apply(process.stderr, [string, encoding, fd]); } }; - debug.enable("log4js:multiFile"); + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:multiFile`); + + t.teardown(async () => { + await new Promise(resolve => { log4js.shutdown(resolve); }); + await removeFiles("logs/D.log"); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + const timeoutMs = 100; log4js.configure({ appenders: { @@ -247,18 +254,11 @@ test("multiFile appender", batch => { `D not used for > ${timeoutMs} ms => close`, "(timeout2) should have closed" ); - if (!debugWasEnabled) { - debug.disable("log4js:multiFile"); - } - process.stderr.write = originalWrite; t.end(); }, timeoutMs*2 + 50); // add a 50 ms delay }); batch.test("should clear interval for active timers on shutdown", t => { - t.teardown(async () => { - await removeFiles("logs/D.log"); - }); /* checking that the file is closed after a timeout is done by looking at the debug logs since detecting file locks with node.js is platform specific. */ @@ -271,7 +271,15 @@ test("multiFile appender", batch => { originalWrite.apply(process.stderr, [string, encoding, fd]); } }; - debug.enable("log4js:multiFile"); + const originalNamespace = debug.disable(); + debug.enable(`${originalNamespace}, log4js:multiFile`); + + t.teardown(async () => { + await removeFiles("logs/D.log"); + process.stderr.write = originalWrite; + debug.enable(originalNamespace); + }); + const timeoutMs = 100; log4js.configure({ appenders: { @@ -302,10 +310,6 @@ test("multiFile appender", batch => { "calling shutdown for D", "should have called shutdown" ); - if (!debugWasEnabled) { - debug.disable("log4js:multiFile"); - } - process.stderr.write = originalWrite; t.end(); }); });