From 654710bd84227b79989353c57c1986fe7d9d029a Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Fri, 4 Feb 2022 17:06:22 +0800 Subject: [PATCH 1/5] chore(test): improve test (branch) coverage for categoryFilter appenders/categoryFilter.js - Line 4 - if (typeof excludes === 'string') excludes = [excludes]; --- test/tap/categoryFilter-test.js | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/test/tap/categoryFilter-test.js b/test/tap/categoryFilter-test.js index b0e153a..4ec52a8 100644 --- a/test/tap/categoryFilter-test.js +++ b/test/tap/categoryFilter-test.js @@ -40,6 +40,38 @@ test("log4js categoryFilter", batch => { t.end(); }); + batch.test("appender should exclude categories", t => { + log4js.configure({ + appenders: { + recorder: { type: "recording" }, + filtered: { + type: "categoryFilter", + exclude: ["app", "web"], + appender: "recorder" + } + }, + categories: { default: { appenders: ["filtered"], level: "DEBUG" } } + }); + + const webLogger = log4js.getLogger("web"); + const appLogger = log4js.getLogger("app"); + + webLogger.debug("This should not get logged"); + appLogger.debug("This should get logged"); + webLogger.debug("Hello again"); + log4js + .getLogger("db") + .debug("This should be included by the appender anyway"); + + const logEvents = recording.replay(); + t.equal(logEvents.length, 1); + t.equal( + logEvents[0].data[0], + "This should be included by the appender anyway" + ); + t.end(); + }); + batch.test("should not really need a category filter any more", t => { log4js.configure({ appenders: { recorder: { type: "recording" } }, From 42eb04e266afaad1bdba9975539b1bba82eb9b4c Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Fri, 4 Feb 2022 17:07:36 +0800 Subject: [PATCH 2/5] chore(test): improve test coverage for adapters appenders/adapters.js - Line 16 - throw Error(`maxLogSize: "${maxLogSize}" is invalid`); --- test/tap/fileAppender-test.js | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/test/tap/fileAppender-test.js b/test/tap/fileAppender-test.js index f325a50..8a11f2e 100644 --- a/test/tap/fileAppender-test.js +++ b/test/tap/fileAppender-test.js @@ -117,6 +117,27 @@ test("log4js fileAppender", batch => { t.end(); }); + batch.test("with a max file size in wrong unit mode", async t => { + const invalidUnit = "1Z"; + const expectedError = new Error(`maxLogSize: "${invalidUnit}" is invalid`); + t.throws( + () => + log4js.configure({ + appenders: { + file: { + type: "file", + maxLogSize: invalidUnit + } + }, + categories: { + default: { appenders: ["file"], level: "debug" } + } + }), + expectedError + ); + t.end(); + }); + batch.test("with a max file size in unit mode and no backups", async t => { const testFile = path.join(__dirname, "fa-maxFileSize-unit-test.log"); const logger = log4js.getLogger("max-file-size-unit"); From d94284aeb81c0c63df4ed0db6fef9a051edd7cb1 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Fri, 4 Feb 2022 17:43:37 +0800 Subject: [PATCH 3/5] chore(test): improve test coverage for fileAppender appenders/file.js - Line 70 - return d; --- test/tap/fileAppender-test.js | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/tap/fileAppender-test.js b/test/tap/fileAppender-test.js index 8a11f2e..95ee8a4 100644 --- a/test/tap/fileAppender-test.js +++ b/test/tap/fileAppender-test.js @@ -386,19 +386,19 @@ test("log4js fileAppender", batch => { }); logger.info("This should be in the file.", - "\x1b[33mColor\x1b[0m \x1b[93;41mshould\x1b[0m be \x1b[38;5;8mplain\x1b[0m."); + "\x1b[33mColor\x1b[0m \x1b[93;41mshould\x1b[0m be \x1b[38;5;8mplain\x1b[0m.", {}, []); await sleep(100); let fileContents = await fs.readFile(testFilePlain, "utf8"); - t.match(fileContents, `This should be in the file. Color should be plain.${EOL}`); + t.match(fileContents, `This should be in the file. Color should be plain. {} []${EOL}`); t.match( fileContents, /\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}] \[INFO] default-settings - / ); - + fileContents = await fs.readFile(testFileAsIs, "utf8"); t.match(fileContents, "This should be in the file.", - `\x1b[33mColor\x1b[0m \x1b[93;41mshould\x1b[0m be \x1b[38;5;8mplain\x1b[0m.${EOL}`); + `\x1b[33mColor\x1b[0m \x1b[93;41mshould\x1b[0m be \x1b[38;5;8mplain\x1b[0m. {} []${EOL}`); t.match( fileContents, /\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}] \[INFO] default-settings - / From 89e70e7fb8f9ca2cf3bb49bd05e5b1d08c03cfbc Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Sat, 5 Feb 2022 16:01:44 +0800 Subject: [PATCH 4/5] chore(test): improve test coverage for multiFileAppender appenders/multiFile.js - Line 53 - timers.get(fileKey).lastUsed = Date.now(); appenders/multiFile.js - Line 70 - clearInterval(timer.interval); --- lib/appenders/multiFile.js | 4 +- test/tap/multi-file-appender-test.js | 124 ++++++++++++++++++++++++++- 2 files changed, 124 insertions(+), 4 deletions(-) diff --git a/lib/appenders/multiFile.js b/lib/appenders/multiFile.js index f15722b..2fd47b8 100644 --- a/lib/appenders/multiFile.js +++ b/lib/appenders/multiFile.js @@ -49,6 +49,7 @@ module.exports.configure = (config, layouts) => { }); } } else if (config.timeout) { + debug('%s extending activity', fileKey); timers.get(fileKey).lastUsed = Date.now(); } @@ -64,7 +65,8 @@ module.exports.configure = (config, layouts) => { cb(); } let error; - timers.forEach((timer) => { + timers.forEach((timer, fileKey) => { + debug('clearing timer for ', fileKey); clearInterval(timer.interval); }); files.forEach((app, fileKey) => { diff --git a/test/tap/multi-file-appender-test.js b/test/tap/multi-file-appender-test.js index 0d69a05..691c6f0 100644 --- a/test/tap/multi-file-appender-test.js +++ b/test/tap/multi-file-appender-test.js @@ -89,6 +89,7 @@ test("multiFile appender", batch => { } }; debug.enable("log4js:multiFile"); + const timeoutMs = 20; log4js.configure({ appenders: { multi: { @@ -96,7 +97,7 @@ test("multiFile appender", batch => { base: "logs/", property: "label", extension: ".log", - timeout: 20 + timeout: timeoutMs } }, categories: { default: { appenders: ["multi"], level: "info" } } @@ -107,14 +108,131 @@ test("multiFile appender", batch => { setTimeout(() => { t.match( debugLogs[debugLogs.length - 1], - "C not used for > 20 ms => close" + `C not used for > ${timeoutMs} ms => close`, + "(timeout1) should have closed" ); if (!debugWasEnabled) { debug.disable("log4js:multiFile"); } process.stderr.write = originalWrite; t.end(); - }, 50); + }, timeoutMs*1 + 30); // add a 30 ms delay + }); + + batch.test("should close file after extended timeout", 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. + */ + const debugWasEnabled = debug.enabled("log4js:multiFile"); + 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]); + } + }; + debug.enable("log4js:multiFile"); + const timeoutMs = 100; + log4js.configure({ + appenders: { + multi: { + type: "multiFile", + base: "logs/", + property: "label", + extension: ".log", + timeout: timeoutMs + } + }, + categories: { default: { appenders: ["multi"], level: "info" } } + }); + const loggerD = log4js.getLogger("cheese"); + loggerD.addContext("label", "D"); + loggerD.info("I am in logger D"); + setTimeout(() => { + loggerD.info("extending activity!"); + t.match( + debugLogs[debugLogs.length - 1], + "D extending activity", + "should have extended" + ); + }, timeoutMs/2); + setTimeout(() => { + t.notOk( + debugLogs.some(s => s.indexOf(`D not used for > ${timeoutMs} ms => close`) !== -1), + "(timeout1) should not have closed" + ); + }, timeoutMs*1 + 30); // add a 30 ms delay + setTimeout(() => { + t.match( + debugLogs[debugLogs.length - 1], + `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 + 30); // add a 30 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. + */ + const debugWasEnabled = debug.enabled("log4js:multiFile"); + 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]); + } + }; + debug.enable("log4js:multiFile"); + const timeoutMs = 100; + log4js.configure({ + appenders: { + multi: { + type: "multiFile", + base: "logs/", + property: "label", + extension: ".log", + timeout: timeoutMs + } + }, + categories: { default: { appenders: ["multi"], level: "info" } } + }); + const loggerD = log4js.getLogger("cheese"); + loggerD.addContext("label", "D"); + loggerD.info("I am in logger D"); + log4js.shutdown(() => { + t.notOk( + debugLogs.some(s => s.indexOf(`D not used for > ${timeoutMs} ms => close`) !== -1), + "should not have closed" + ); + t.ok( + debugLogs.some(s => s.indexOf("clearing timer for D") !== -1), + "should have cleared timers" + ); + t.match( + debugLogs[debugLogs.length - 1], + "calling shutdown for D", + "should have called shutdown" + ); + if (!debugWasEnabled) { + debug.disable("log4js:multiFile"); + } + process.stderr.write = originalWrite; + t.end(); + }); }); batch.test( From 4a0f6e4e2027f5f4d3698c9e2a2b63c6658b769d Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Wed, 19 Jan 2022 01:57:25 +0800 Subject: [PATCH 5/5] chore(test): Changed default TAP test suite timeout from 30s to 45s because Windows takes a long time --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 8cf7640..ff70374 100644 --- a/package.json +++ b/package.json @@ -34,7 +34,7 @@ }, "scripts": { "pretest": "eslint \"lib/**/*.js\" \"test/**/*.js\"", - "test": "tap \"test/tap/**/*.js\" --cov", + "test": "tap \"test/tap/**/*.js\" --cov --timeout=45", "typings": "tsc -p types/tsconfig.json", "codecov": "tap \"test/tap/**/*.js\" --cov --coverage-report=lcov && codecov" },