From aa566df3f80baeaddb09c009ccf675e42de43c96 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Tue, 8 Mar 2022 23:25:43 +0800 Subject: [PATCH 1/5] chore(test): improve test coverage for fileSyncAppender appenders/fileSync.js - Line 11 - return; --- test/tap/fileSyncAppender-test.js | 36 +++++++++++++++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/test/tap/fileSyncAppender-test.js b/test/tap/fileSyncAppender-test.js index f6a2eb2..b36e3b0 100644 --- a/test/tap/fileSyncAppender-test.js +++ b/test/tap/fileSyncAppender-test.js @@ -40,6 +40,42 @@ test("log4js fileSyncAppender", batch => { }); }); + batch.test("with existing file", t => { + const testFile = path.join(__dirname, "/fa-existing-file-sync-test.log"); + const logger = log4js.getLogger("default-settings"); + remove(testFile); + + t.teardown(() => { + remove(testFile); + }); + + log4js.configure({ + appenders: { sync: { type: "fileSync", filename: testFile } }, + categories: { default: { appenders: ["sync"], level: "debug" } } + }); + + logger.info("This should be in the file."); + + log4js.shutdown(() => { + log4js.configure({ + appenders: { sync: { type: "fileSync", filename: testFile } }, + categories: { default: { appenders: ["sync"], level: "debug" } } + }); + + logger.info("This should also be in the file."); + + fs.readFile(testFile, "utf8", (err, fileContents) => { + t.match(fileContents, `This should be in the file.${EOL}`); + t.match(fileContents, `This should also be in the file.${EOL}`); + t.match( + fileContents, + /\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}] \[INFO] default-settings - / + ); + t.end(); + }); + }); + }); + batch.test("should give error if invalid filename", async t => { const file = ""; const expectedError = new Error(`Invalid filename: ${file}`); From edc612e5bea40f044447d6cd410853446efc3922 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Tue, 8 Mar 2022 23:43:36 +0800 Subject: [PATCH 2/5] chore(test): improve test coverage for dateFileAppender appenders/dateFile.js - Line 13 - console.error('log4js.dateFileAppender - Writing to file %s, error happened ', filename, err); // eslint-disable-line --- test/tap/dateFileAppender-test.js | 55 +++++++++++++++++++++++++++++++ 1 file changed, 55 insertions(+) diff --git a/test/tap/dateFileAppender-test.js b/test/tap/dateFileAppender-test.js index c224a96..e48d101 100644 --- a/test/tap/dateFileAppender-test.js +++ b/test/tap/dateFileAppender-test.js @@ -188,5 +188,60 @@ test("../../lib/appenders/dateFile", batch => { t.end(); }); + batch.test("when underlying stream errors", t => { + let consoleArgs; + let errorHandler; + + const DateRollingFileStream = class { + end() { + this.ended = true; + } + + on(evt, cb) { + if (evt === "error") { + this.errored = true; + errorHandler = cb; + } + } + + write() { + this.written = true; + return true; + } + }; + const dateFileAppender = sandbox.require("../../lib/appenders/dateFile", { + globals: { + console: { + error(...args) { + consoleArgs = args; + } + } + }, + requires: { + streamroller: { + DateRollingFileStream + } + } + }); + + dateFileAppender.configure( + { filename: "test1.log", maxLogSize: 100 }, + { basicLayout() {} } + ); + errorHandler({ error: "aargh" }); + + t.test("should log the error to console.error", assert => { + assert.ok(consoleArgs); + assert.equal( + consoleArgs[0], + "log4js.dateFileAppender - Writing to file %s, error happened " + ); + assert.equal(consoleArgs[1], "test1.log"); + assert.equal(consoleArgs[2].error, "aargh"); + assert.end(); + }); + t.end(); + }); + batch.end(); }); From 633b4222ab52c05cdb40f54efcdda28b415d84eb Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Wed, 9 Mar 2022 23:36:42 +0800 Subject: [PATCH 3/5] chore(test): improve test coverage for tcpAppender appenders/tcp.js - Line 37 - debug('drain event received, emptying buffer'); appenders/tcp.js - Line 38 - canWrite = true; appenders/tcp.js - Line 39 - emptyBuffer(); appenders/tcp.js - Line 43 - debug('connection error', e); appenders/tcp.js - Line 44 - canWrite = false; appenders/tcp.js - Line 45 - emptyBuffer(); appenders/tcp.js - Line 54 - write(loggingEvent); --- test/tap/tcp-appender-test.js | 149 +++++++++++++++++++++++++++++++++- 1 file changed, 148 insertions(+), 1 deletion(-) diff --git a/test/tap/tcp-appender-test.js b/test/tap/tcp-appender-test.js index e61255f..293f682 100644 --- a/test/tap/tcp-appender-test.js +++ b/test/tap/tcp-appender-test.js @@ -1,5 +1,7 @@ const { test } = require("tap"); const net = require("net"); +const flatted = require("flatted"); +const sandbox = require("@log4js-node/sandboxed-module"); const log4js = require("../../lib/log4js"); const LoggingEvent = require("../../lib/LoggingEvent"); @@ -26,6 +28,53 @@ function makeServer(config) { return server; } +function makeFakeNet() { + return { + data: [], + cbs: {}, + createConnectionCalled: 0, + createConnection(port, host) { + const fakeNet = this; + this.port = port; + this.host = host; + this.createConnectionCalled += 1; + return { + on(evt, cb) { + fakeNet.cbs[evt] = cb; + }, + write(data, encoding) { + fakeNet.data.push(data); + fakeNet.encoding = encoding; + return false; + }, + end() { + fakeNet.closeCalled = true; + } + }; + }, + createServer(cb) { + const fakeNet = this; + cb({ + remoteAddress: "1.2.3.4", + remotePort: "1234", + setEncoding(encoding) { + fakeNet.encoding = encoding; + }, + on(event, cb2) { + fakeNet.cbs[event] = cb2; + } + }); + + return { + listen(port, host) { + fakeNet.port = port; + fakeNet.host = host; + } + }; + } + }; +} + test("TCP Appender", batch => { batch.test("Default Configuration", t => { @@ -118,7 +167,6 @@ test("TCP Appender", batch => { }); }); - batch.test("Custom Layout", t => { messages = []; @@ -171,5 +219,104 @@ test("TCP Appender", batch => { }); }); + batch.test("when underlying stream errors", t => { + const fakeNet = makeFakeNet(); + + const sandboxedLog4js = sandbox.require("../../lib/log4js", { + requires: { + net: fakeNet + } + }); + sandboxedLog4js.configure({ + appenders: { + default: { type: "tcp" }, + }, + categories: { + default: { appenders: ["default"], level: "debug" }, + } + }); + + const logger = sandboxedLog4js.getLogger(); + + logger.info("before connect"); + t.test( + "should buffer messages written before socket is connected", + assert => { + assert.equal(fakeNet.data.length, 0); + assert.equal(fakeNet.createConnectionCalled, 1); + assert.end(); + } + ); + + fakeNet.cbs.connect(); + t.test( + "should flush buffered messages", + assert => { + assert.equal(fakeNet.data.length, 1); + assert.equal(fakeNet.createConnectionCalled, 1); + assert.match(fakeNet.data[0], "before connect"); + assert.end(); + } + ); + + logger.info("after connect"); + t.test( + "should write log messages to socket as flatted strings with a terminator string", + assert => { + assert.equal(fakeNet.data.length, 2); + assert.match(fakeNet.data[0], "before connect"); + assert.ok(fakeNet.data[0].endsWith("__LOG4JS__")); + assert.match(fakeNet.data[1], "after connect"); + assert.ok(fakeNet.data[1].endsWith("__LOG4JS__")); + assert.equal(fakeNet.encoding, "utf8"); + assert.end(); + } + ); + + fakeNet.cbs.error(); + logger.info("after error, before close"); + fakeNet.cbs.close(); + logger.info("after close, before connect"); + fakeNet.cbs.connect(); + logger.info("after error, after connect"); + t.test("should attempt to re-open the socket on error", assert => { + assert.equal(fakeNet.data.length, 5); + assert.equal(fakeNet.createConnectionCalled, 2); + assert.match(fakeNet.data[2], "after error, before close"); + assert.match(fakeNet.data[3], "after close, before connect"); + assert.match(fakeNet.data[4], "after error, after connect"); + assert.end(); + }); + + t.test("should buffer messages until drain", assert => { + const previousLength = fakeNet.data.length; + logger.info("should not be flushed"); + assert.equal(fakeNet.data.length, previousLength); + assert.notMatch(fakeNet.data[fakeNet.data.length - 1], "should not be flushed"); + + fakeNet.cbs.drain(); + assert.equal(fakeNet.data.length, previousLength + 1); + assert.match(fakeNet.data[fakeNet.data.length - 1], "should not be flushed"); + assert.end(); + }); + + t.test("should serialize an Error correctly", assert => { + const previousLength = fakeNet.data.length; + logger.error(new Error("Error test")); + fakeNet.cbs.drain(); + assert.equal(fakeNet.data.length, previousLength + 1); + const raw = fakeNet.data[fakeNet.data.length - 1]; + assert.ok( + flatted.parse(raw.substring(0, raw.indexOf('__LOG4JS__'))).data[0].stack, + `Expected:\n\n${fakeNet.data[6]}\n\n to have a 'data[0].stack' property` + ); + const actual = flatted.parse(raw.substring(0, raw.indexOf('__LOG4JS__'))).data[0].stack; + assert.match(actual, /^Error: Error test/); + assert.end(); + }); + + t.end(); + }); + batch.end(); }); From c556a1a5320dccdf9d4797acc389a0f7bd6f43a5 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Thu, 10 Mar 2022 00:56:36 +0800 Subject: [PATCH 4/5] chore(test): improve test coverage for fileAppender and dateFileAppender appenders/file.js - Line 56 - process.emit("log4js:pause", false); appenders/dateFile.js - Line 16 - process.emit("log4js:pause", false); --- test/tap/pause-test.js | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/test/tap/pause-test.js b/test/tap/pause-test.js index fc8ef6c..c4d00c6 100644 --- a/test/tap/pause-test.js +++ b/test/tap/pause-test.js @@ -13,6 +13,7 @@ tap.test("Drain event test", batch => { batch.test("Should emit pause event and resume when logging in a file with high frequency", t => { t.teardown(async () => { + process.off("log4js:pause", process.listeners("log4js:pause")[process.listeners("log4js:pause").length - 1]); await removeFiles("logs/drain.log"); }); // Generate logger with 5k of highWaterMark config @@ -31,8 +32,11 @@ tap.test("Drain event test", batch => { process.on("log4js:pause", value => { if (value) { paused = true; + t.ok(value, "log4js:pause, true"); } else { resumed = true; + t.ok(!value, "log4js:pause, false"); + t.end(); } }); @@ -42,12 +46,12 @@ tap.test("Drain event test", batch => { logger.info("This is a test for emitting drain event"); } } - t.end(); }); batch.test("Should emit pause event and resume when logging in a date file with high frequency", (t) => { t.teardown(async () => { + process.off("log4js:pause", process.listeners("log4js:pause")[process.listeners("log4js:pause").length - 1]); await removeFiles("logs/date-file-drain.log"); }); // Generate date file logger with 5kb of highWaterMark config @@ -66,8 +70,11 @@ tap.test("Drain event test", batch => { process.on("log4js:pause", value => { if (value) { paused = true; + t.ok(value, "log4js:pause, true"); } else { resumed = true; + t.ok(!value, "log4js:pause, false"); + t.end(); } }); @@ -76,7 +83,6 @@ tap.test("Drain event test", batch => { if (!paused) logger.info("This is a test for emitting drain event in date file logger"); } - t.end(); }); batch.teardown(async () => { From 0abf8a601d15383bd252bb516b6c8750054dd758 Mon Sep 17 00:00:00 2001 From: Lam Wei Li Date: Thu, 10 Mar 2022 01:02:18 +0800 Subject: [PATCH 5/5] chore(test): increased timeout for multi-file-appender-test.js --- test/tap/multi-file-appender-test.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/tap/multi-file-appender-test.js b/test/tap/multi-file-appender-test.js index 8969d87..038ccdc 100644 --- a/test/tap/multi-file-appender-test.js +++ b/test/tap/multi-file-appender-test.js @@ -91,7 +91,7 @@ test("multiFile appender", batch => { } }; debug.enable("log4js:multiFile"); - const timeoutMs = 20; + const timeoutMs = 25; log4js.configure({ appenders: { multi: { @@ -118,7 +118,7 @@ test("multiFile appender", batch => { } process.stderr.write = originalWrite; t.end(); - }, timeoutMs*1 + 30); // add a 30 ms delay + }, timeoutMs*1 + 50); // add a 50 ms delay }); batch.test("should close file safely after timeout", t => { @@ -158,7 +158,7 @@ test("multiFile appender", batch => { } }; debug.enable("log4js:multiFile"); - const timeoutMs = 20; + const timeoutMs = 25; sandboxedLog4js.configure({ appenders: { multi: { @@ -190,7 +190,7 @@ test("multiFile appender", batch => { } process.stderr.write = originalWrite; t.end(); - }, timeoutMs*1 + 30); // add a 30 ms delay + }, timeoutMs*1 + 50); // add a 50 ms delay }); batch.test("should close file after extended timeout", t => { @@ -240,7 +240,7 @@ test("multiFile appender", batch => { 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 + }, timeoutMs*1 + 50); // add a 50 ms delay setTimeout(() => { t.match( debugLogs[debugLogs.length - 1], @@ -252,7 +252,7 @@ test("multiFile appender", batch => { } process.stderr.write = originalWrite; t.end(); - }, timeoutMs*2 + 30); // add a 30 ms delay + }, timeoutMs*2 + 50); // add a 50 ms delay }); batch.test("should clear interval for active timers on shutdown", t => {