Merge pull request #1204 from log4js-node/update-test

chore(test): improve test coverage

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

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}`);

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

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

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