From 65fe707350f029509063dae1bd181ac5344df182 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Fri, 4 Mar 2022 22:03:38 +0800 Subject: [PATCH 01/11] chore(test): improve test coverage for multiprocessAppender appenders/multiprocess.js - Line 121 - debug('connection error', e); appenders/multiprocess.js - Line 122 - canWrite = false; appenders/multiprocess.js - Line 123 - emptyBuffer(); --- test/tap/multiprocess-test.js | 41 ++++++++++++++++++++++++++++++++++- 1 file changed, 40 insertions(+), 1 deletion(-) diff --git a/test/tap/multiprocess-test.js b/test/tap/multiprocess-test.js index 6901939..2013ed7 100644 --- a/test/tap/multiprocess-test.js +++ b/test/tap/multiprocess-test.js @@ -79,7 +79,7 @@ test("Multiprocess Appender", async batch => { logger.info("before connect"); fakeNet.cbs.connect(); logger.info("after connect"); - fakeNet.cbs.close(true); + fakeNet.cbs.close(); logger.info("after error, before connect"); fakeNet.cbs.connect(); logger.info("after error, after connect"); @@ -173,6 +173,45 @@ test("Multiprocess Appender", async batch => { t.end(); }); + batch.test("worker with error", t => { + const fakeNet = makeFakeNet(); + + const log4js = sandbox.require("../../lib/log4js", { + requires: { + net: fakeNet + } + }); + log4js.configure({ + appenders: { worker: { type: "multiprocess", mode: "worker" } }, + categories: { default: { appenders: ["worker"], level: "trace" } } + }); + + const logger = log4js.getLogger(); + logger.info("before connect"); + fakeNet.cbs.connect(); + logger.info("after connect"); + fakeNet.cbs.error(); + logger.info("after error, before close"); + fakeNet.cbs.close(); + logger.info("after close, before connect"); + fakeNet.cbs.connect(); + logger.info("after close, after connect"); + + const net = fakeNet; + + t.test("should attempt to re-open the socket", assert => { + // skipping the __LOG4JS__ separators + assert.match(net.data[0], "before connect"); + assert.match(net.data[2], "after connect"); + assert.match(net.data[4], "after error, before close"); + assert.match(net.data[6], "after close, before connect"); + assert.match(net.data[8], "after close, after connect"); + assert.equal(net.createConnectionCalled, 2); + assert.end(); + }); + t.end(); + }); + batch.test("worker defaults", t => { const fakeNet = makeFakeNet(); From 64ef06b849fe9ebf5d44faedaaaf1f2e42fd595e Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Fri, 4 Mar 2022 22:11:00 +0800 Subject: [PATCH 02/11] chore(test): improve test coverage for tcp-serverAppender appenders/tcp-server.js - Line 19 - dataSoFar = events.pop(); appenders/tcp-server.js - Line 27 - dataSoFar = ''; --- test/tap/server-test.js | 131 ++++++++++++++++++++++++++++++++++++---- 1 file changed, 118 insertions(+), 13 deletions(-) diff --git a/test/tap/server-test.js b/test/tap/server-test.js index a2b7416..d56c282 100644 --- a/test/tap/server-test.js +++ b/test/tap/server-test.js @@ -5,21 +5,20 @@ const vcr = require("../../lib/appenders/recording"); const levels = require("../../lib/levels"); const LoggingEvent = require("../../lib/LoggingEvent"); -log4js.configure({ - appenders: { - vcr: { type: "recording" }, - tcp: { type: "tcp-server", port: 5678 } - }, - categories: { - default: { appenders: ["vcr"], level: "debug" } - } -}); - -// give the socket a chance to start up test("TCP Server", batch => { batch.test( "should listen for TCP messages and re-send via process.send", t => { + log4js.configure({ + appenders: { + vcr: { type: "recording" }, + tcp: { type: "tcp-server", port: 5678 } + }, + categories: { + default: { appenders: ["vcr"], level: "debug" } + } + }); + // give the socket a chance to start up setTimeout(() => { const socket = net.connect(5678, () => { socket.write( @@ -83,8 +82,114 @@ test("TCP Server", batch => { socket.unref(); }, 100); - - batch.end(); } ); + + batch.test( + "sending incomplete messages in chunks", + t => { + log4js.configure({ + appenders: { + vcr: { type: "recording" }, + tcp: { type: "tcp-server" } + }, + categories: { + default: { appenders: ["vcr"], level: "debug" } + } + }); + // give the socket a chance to start up + setTimeout(() => { + const socket = net.connect(5000, () => { + const syncWrite = (dataArray = [], finalCallback) => { + if (dataArray === null) { + dataArray = []; + } else if (!Array.isArray(dataArray)) { + dataArray = [dataArray]; + } + if (typeof finalCallback !== "function") { + finalCallback = () => {}; + } + setTimeout(() => { + if (!dataArray.length) { + finalCallback(); + } else if (dataArray.length === 1) { + socket.write(dataArray.shift(), finalCallback); + } else { + socket.write(dataArray.shift(), () => { syncWrite(dataArray, finalCallback); }); + } + }, 100); + }; + + const dataArray = [ + "__LOG4JS__", + "Hello__LOG4JS__World", + "__LOG4JS__", + "testing nonsense", + `__LOG4JS__more nonsense__LOG4JS__` + ]; + + const finalCallback = () => { + socket.end(); + setTimeout(() => { + log4js.shutdown(() => { + const logs = vcr.replay(); + t.equal(logs.length, 8); + t.match(logs[4], { + data: [ + "Unable to parse log:", + "Hello", + "because: ", + SyntaxError + ], + categoryName: "log4js", + level: { levelStr: "ERROR" }, + context: {} + }); + t.match(logs[5], { + data: [ + "Unable to parse log:", + "World", + "because: ", + SyntaxError + ], + categoryName: "log4js", + level: { levelStr: "ERROR" }, + context: {} + }); + t.match(logs[6], { + data: [ + "Unable to parse log:", + "testing nonsense", + "because: ", + SyntaxError + ], + categoryName: "log4js", + level: { levelStr: "ERROR" }, + context: {} + }); + t.match(logs[7], { + data: [ + "Unable to parse log:", + "more nonsense", + "because: ", + SyntaxError + ], + categoryName: "log4js", + level: { levelStr: "ERROR" }, + context: {} + }); + t.end(); + }); + }, 100); + }; + + syncWrite(dataArray, finalCallback); + }); + + socket.unref(); + }, 100); + } + ); + + batch.end(); }); From 04bd18b44d17b7c060c18e4a6084a9d3714399ba Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Sat, 5 Mar 2022 01:51:39 +0800 Subject: [PATCH 03/11] chore(test): improve test coverage for appenders/index (requires truthy value, used a noop function, but the function never gets called anyway) appenders/index.js - Line 95 - }, /* istanbul ignore next */ () => {}); --- lib/appenders/index.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/appenders/index.js b/lib/appenders/index.js index 58b10c1..2039dab 100644 --- a/lib/appenders/index.js +++ b/lib/appenders/index.js @@ -92,7 +92,7 @@ const createAppender = (name, config) => { appender => getAppender(appender, config), levels ); - }, () => { }); + }, /* istanbul ignore next */ () => {}); }; const setup = (config) => { From a912401dc2a451d56a645af9659f667d57a1a84f Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Sat, 5 Mar 2022 01:58:58 +0800 Subject: [PATCH 04/11] chore(test): improve test coverage for appenders/index appenders/index.js - Line 78 - process.emitWarning( appenders/index.js - Line 79 - `Appender ${appenderConfig.type} exports a shutdown function.`, appenders/index.js - Line 80 - "DeprecationWarning", "log4js-node-DEP0002" appenders/index.js - Line 81 - ); appenders/index.js - Line 82 - debug(`DEPRECATION: Appender ${appenderConfig.type} exports a shutdown function.`); --- test/tap/default-settings-test.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/tap/default-settings-test.js b/test/tap/default-settings-test.js index ec9f8c0..f1816aa 100644 --- a/test/tap/default-settings-test.js +++ b/test/tap/default-settings-test.js @@ -13,6 +13,8 @@ test("default settings", t => { output.push(evt); }; }, + shutdown() { + }, configure() { return this.appender(); } From 05a64ff1fe25150ed92d17964819c9c19cc6888f Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Mon, 7 Mar 2022 00:19:14 +0800 Subject: [PATCH 05/11] chore(test): improve test coverage for log4js log4js.js - Line 83 - return recordingModule --- test/tap/recordingAppender-test.js | 28 ++++++++++++++++++++++++++++ types/test.ts | 5 ++++- 2 files changed, 32 insertions(+), 1 deletion(-) create mode 100644 test/tap/recordingAppender-test.js diff --git a/test/tap/recordingAppender-test.js b/test/tap/recordingAppender-test.js new file mode 100644 index 0000000..142f6e1 --- /dev/null +++ b/test/tap/recordingAppender-test.js @@ -0,0 +1,28 @@ +const { test } = require("tap"); +const log4js = require("../../lib/log4js"); + +test("recording appender", t => { + log4js.configure({ + appenders: { rec: { type: 'recording' } }, + categories: { default: { appenders: [ 'rec' ], 'level': 'debug' } } + }); + + const logger = log4js.getLogger(); + logger.level = 'debug'; + logger.debug('This will go to the recording!'); + logger.debug('Another one'); + + const recording = log4js.recording(); + const loggingEvents = recording.playback(); + + t.equal(loggingEvents.length, 2, "There should be 2 recorded events"); + t.equal(loggingEvents[0].data[0], "This will go to the recording!"); + t.equal(loggingEvents[1].data[0], "Another one"); + + recording.reset(); + const loggingEventsPostReset = recording.playback(); + + t.equal(loggingEventsPostReset.length, 0, "There should be 0 recorded events"); + + t.end(); +}); diff --git a/types/test.ts b/types/test.ts index b0c8d4e..b7bb8f3 100644 --- a/types/test.ts +++ b/types/test.ts @@ -139,7 +139,7 @@ log4js.configure({ log4js.configure({ appenders: { rec: { type: 'recording' } }, - categories: { default: { appenders: [ 'rec'], 'level': 'debug' } } + categories: { default: { appenders: ['rec'], 'level': 'debug' } } }); const logger8 = log4js.getLogger(); logger8.level = 'debug' @@ -150,6 +150,9 @@ const loggingEvents = recording.playback() if (loggingEvents.length !== 2) { throw new Error(`Expected 2 recorded events, got ${loggingEvents.length}`) } +if (loggingEvents[0].data[0] !== 'This will go to the recording!') { + throw new Error(`Expected message 'This will go to the recording!', got ${loggingEvents[0].data[0]}`) +} if (loggingEvents[1].data[0] !== 'Another one') { throw new Error(`Expected message 'Another one', got ${loggingEvents[1].data[0]}`) } From 70b69ea187784f1fd904ec2e0d942f6f78397da4 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Mon, 7 Mar 2022 01:11:32 +0800 Subject: [PATCH 06/11] chore(test): improve test coverage for log4js log4js.js - Line 37 - if (!enabled) return; --- test/tap/logging-test.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/tap/logging-test.js b/test/tap/logging-test.js index 7943f0c..9cfdab8 100644 --- a/test/tap/logging-test.js +++ b/test/tap/logging-test.js @@ -154,6 +154,8 @@ test("log4js", batch => { "should invoke appender shutdowns" ); logger.info("this should not go to the appenders"); + logger.log("info", "this should not go to the appenders"); + logger._log(require("../../lib/levels").INFO, ["this should not go to the appenders"]); t.notOk(events.event); t.end(); }); From f7489941db3191e03c03faac03c9ce72b029c38f Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Mon, 7 Mar 2022 12:45:32 +0800 Subject: [PATCH 07/11] chore(test): tap.teardown() to await for log4js.shutdown() or removeFiles() --- test/tap/configuration-validation-test.js | 4 ++-- test/tap/file-descriptor-leak-test.js | 2 +- test/tap/file-sighup-test.js | 2 +- test/tap/fileAppender-test.js | 6 +++--- 4 files changed, 7 insertions(+), 7 deletions(-) diff --git a/test/tap/configuration-validation-test.js b/test/tap/configuration-validation-test.js index b560146..5f22137 100644 --- a/test/tap/configuration-validation-test.js +++ b/test/tap/configuration-validation-test.js @@ -256,8 +256,8 @@ test("log4js configuration validation", batch => { batch.test("should not throw error if configure object is freezed", t => { const testFile = "test/tap/freeze-date-file-test"; - t.teardown(() => { - removeFiles(testFile); + t.teardown(async () => { + await removeFiles(testFile); }); t.doesNotThrow(() => log4js.configure( diff --git a/test/tap/file-descriptor-leak-test.js b/test/tap/file-descriptor-leak-test.js index 7436a8e..6a899f8 100644 --- a/test/tap/file-descriptor-leak-test.js +++ b/test/tap/file-descriptor-leak-test.js @@ -68,7 +68,7 @@ if (process.platform !== "win32") { }); batch.teardown(async () => { - log4js.shutdown(); + await new Promise(resolve => log4js.shutdown(resolve)); const filenames = Object.values(config.appenders).map(appender => appender.filename); await removeFiles(filenames); diff --git a/test/tap/file-sighup-test.js b/test/tap/file-sighup-test.js index cf059b2..d8fba5e 100644 --- a/test/tap/file-sighup-test.js +++ b/test/tap/file-sighup-test.js @@ -39,7 +39,7 @@ test("file appender single SIGHUP handler", t => { log4js.configure(config); t.teardown(async () => { - log4js.shutdown(); + await new Promise(resolve => log4js.shutdown(resolve)); const filenames = Object.values(config.appenders).map(appender => appender.filename); await removeFiles(filenames); diff --git a/test/tap/fileAppender-test.js b/test/tap/fileAppender-test.js index 17f3b4b..b379a06 100644 --- a/test/tap/fileAppender-test.js +++ b/test/tap/fileAppender-test.js @@ -69,6 +69,7 @@ test("log4js fileAppender", batch => { batch.test("should flush logs on shutdown", async t => { const testFile = path.join(__dirname, "fa-default-test.log"); + const logger = log4js.getLogger("default-settings"); await removeFile(testFile); t.teardown(async () => { @@ -80,7 +81,6 @@ test("log4js fileAppender", batch => { appenders: { test: { type: "file", filename: testFile } }, categories: { default: { appenders: ["test"], level: "trace" } } }); - const logger = log4js.getLogger("default-settings"); logger.info("1"); logger.info("2"); @@ -100,12 +100,12 @@ test("log4js fileAppender", batch => { batch.test("with a max file size and no backups", async t => { const testFile = path.join(__dirname, "fa-maxFileSize-test.log"); const logger = log4js.getLogger("max-file-size"); + await removeFile(testFile); t.teardown(async () => { await new Promise(resolve => log4js.shutdown(resolve)); await removeFile(testFile); }); - await removeFile(testFile); // log file of 100 bytes maximum, no backups log4js.configure({ @@ -162,12 +162,12 @@ test("log4js fileAppender", batch => { 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"); + await Promise.all([removeFile(testFile), removeFile(`${testFile}.1`)]); t.teardown(async () => { await new Promise(resolve => log4js.shutdown(resolve)); await Promise.all([removeFile(testFile), removeFile(`${testFile}.1`)]); }); - await Promise.all([removeFile(testFile), removeFile(`${testFile}.1`)]); // log file of 1K = 1024 bytes maximum, no backups log4js.configure({ From f5a9d13313c006448230277e74cbf51495ba2177 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Sun, 6 Mar 2022 22:56:44 +0800 Subject: [PATCH 08/11] chore(test): improve test coverage for multiFileAppender appenders/multiFile.js - Line 25 - debug('ignore error on file shutdown: %s', err.message); --- test/tap/multi-file-appender-test.js | 72 ++++++++++++++++++++++++++++ 1 file changed, 72 insertions(+) diff --git a/test/tap/multi-file-appender-test.js b/test/tap/multi-file-appender-test.js index 691c6f0..b827fa6 100644 --- a/test/tap/multi-file-appender-test.js +++ b/test/tap/multi-file-appender-test.js @@ -2,6 +2,7 @@ const process = require("process"); const { test } = require("tap"); const debug = require("debug"); const fs = require("fs"); +const sandbox = require("@log4js-node/sandboxed-module"); const log4js = require("../../lib/log4js"); const removeFiles = async filenames => { @@ -119,6 +120,77 @@ test("multiFile appender", batch => { }, timeoutMs*1 + 30); // add a 30 ms delay }); + batch.test("should close file safely after timeout", t => { + t.teardown(async () => { + await removeFiles("logs/C.log"); + }); + const error = new Error("fileAppender shutdown error"); + const sandboxedLog4js = sandbox.require("../../lib/log4js", { + requires: { + "./appenders/file": { + configure(config, layouts) { + const fileAppender = require("../../lib/appenders/file").configure(config, layouts); + const originalShutdown = fileAppender.shutdown; + fileAppender.shutdown = function (complete) { + const onCallback = function() { + complete(error); + }; + originalShutdown(onCallback); + }; + return fileAppender; + } + }, + debug + } + }); + /* 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 = 20; + sandboxedLog4js.configure({ + appenders: { + multi: { + type: "multiFile", + base: "logs/", + property: "label", + extension: ".log", + timeout: timeoutMs + } + }, + categories: { default: { appenders: ["multi"], level: "info" } } + }); + const loggerC = sandboxedLog4js.getLogger("cheese"); + loggerC.addContext("label", "C"); + loggerC.info("I am in logger C"); + setTimeout(() => { + t.match( + debugLogs[debugLogs.length - 2], + `C not used for > ${timeoutMs} ms => close`, + "(timeout1) should have closed" + ); + t.match( + debugLogs[debugLogs.length - 1], + `ignore error on file shutdown: ${error.message}`, + "safely shutdown" + ); + if (!debugWasEnabled) { + debug.disable("log4js:multiFile"); + } + process.stderr.write = originalWrite; + t.end(); + }, 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"); From 905a513cf6fb4c1815be41ae8259991f8a9c41da Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Tue, 8 Mar 2022 15:33:38 +0800 Subject: [PATCH 09/11] chore(test): update multiFileAppender tests to teardown so as not to affect the next test --- test/tap/multi-file-appender-test.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/test/tap/multi-file-appender-test.js b/test/tap/multi-file-appender-test.js index b827fa6..8969d87 100644 --- a/test/tap/multi-file-appender-test.js +++ b/test/tap/multi-file-appender-test.js @@ -75,6 +75,7 @@ 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 @@ -122,6 +123,7 @@ test("multiFile appender", batch => { 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"); @@ -193,6 +195,7 @@ test("multiFile appender", batch => { 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 From 6e6dbad5d34d908ac65eb30e3655ac1075313502 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Sun, 6 Mar 2022 23:10:45 +0800 Subject: [PATCH 10/11] chore(test): improve test coverage for multiFileAppender (else path will never be taken) appenders/multiFile.js - Line 17 - /* istanbul ignore else */ appenders/multiFile.js - Line 18 - if (timer && app) { --- lib/appenders/multiFile.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/appenders/multiFile.js b/lib/appenders/multiFile.js index 2fd47b8..f981c3f 100644 --- a/lib/appenders/multiFile.js +++ b/lib/appenders/multiFile.js @@ -14,6 +14,7 @@ module.exports.configure = (config, layouts) => { function checkForTimeout(fileKey) { const timer = timers.get(fileKey); const app = files.get(fileKey); + /* istanbul ignore else */ if (timer && app) { if (Date.now() - timer.lastUsed > timer.timeout) { debug('%s not used for > %d ms => close', fileKey, timer.timeout); From 8ad41831d1fcbc1d2d17d75ac5281820005f10d6 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Tue, 8 Mar 2022 17:22:12 +0800 Subject: [PATCH 11/11] chore(test): improve test coverage for fileSyncAppender appenders/fileSync.js - Line 58 - throw new Error(`maxLogSize (${maxLogSize}) should be > 0`); --- lib/appenders/fileSync.js | 12 ++++-------- test/tap/fileSyncAppender-test.js | 22 ++++++++++++++++++++++ 2 files changed, 26 insertions(+), 8 deletions(-) diff --git a/lib/appenders/fileSync.js b/lib/appenders/fileSync.js index 995ed78..071ea9e 100755 --- a/lib/appenders/fileSync.js +++ b/lib/appenders/fileSync.js @@ -51,19 +51,15 @@ function touchFile(file, options) { } class RollingFileSync { - constructor(filename, size, backups, options) { + constructor(filename, maxLogSize, backups, options) { debug('In RollingFileStream'); - function throwErrorIfArgumentsAreNotValid() { - if (!filename || !size || size <= 0) { - throw new Error('You must specify a filename and file size'); - } + if (maxLogSize < 0) { + throw new Error(`maxLogSize (${maxLogSize}) should be > 0`); } - throwErrorIfArgumentsAreNotValid(); - this.filename = filename; - this.size = size; + this.size = maxLogSize; this.backups = backups; this.options = options; this.currentSize = 0; diff --git a/test/tap/fileSyncAppender-test.js b/test/tap/fileSyncAppender-test.js index c7f0190..f6a2eb2 100644 --- a/test/tap/fileSyncAppender-test.js +++ b/test/tap/fileSyncAppender-test.js @@ -61,6 +61,28 @@ test("log4js fileSyncAppender", batch => { t.end(); }); + batch.test("should give error if invalid maxLogSize", async t => { + const maxLogSize = -1; + const expectedError = new Error(`maxLogSize (${maxLogSize}) should be > 0`); + t.throws( + () => + log4js.configure({ + appenders: { + file: { + type: "fileSync", + filename: path.join(__dirname, "fa-invalidMaxFileSize-sync-test.log"), + maxLogSize: -1 + } + }, + categories: { + default: { appenders: ["file"], level: "debug" } + } + }), + expectedError + ); + t.end(); + }); + batch.test("with a max file size and no backups", t => { const testFile = path.join(__dirname, "/fa-maxFileSize-sync-test.log"); const logger = log4js.getLogger("max-file-size");