Log4js 6.3 crashes on linux when using the multiprocess appender

[nicojs]

Version 6.3 isn't working anymore for Stryker on linux. We're using the multiprocess appender. After starting it in worker mode we get these errors:

     '\tError: connect ECONNREFUSED 127.0.0.1:43793\n' +
    '\t    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1141:16)\n' +
    "\tEmitted 'error' event on Socket instance at:\n" +
    '\t    at emitErrorNT (internal/streams/destroy.js:92:8)\n' +
    '\t    at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)\n' +
    '\t    at processTicksAndRejections (internal/process/task_queues.js:84:21) {\n' +
    "\t  errno: 'ECONNREFUSED',\n" +
    "\t  code: 'ECONNREFUSED',\n" +
    "\t  syscall: 'connect',\n" +
    "\t  address: '127.0.0.1',\n" +
    '\t  port: 43793\n' +

In CI/CD https://github.com/stryker-mutator/stryker/runs/941753327?check_suite_focus=true.

I was able to reproduce on WSL.

Will try to create detailed reproduction in the coming days. I don't see a lot of code changes, the only substantial commit seems to be 3cb7f52

I don't know why this would break the multiprocess appender. Maybe @nomiddlename already has a hunch? 😅

[lamweili]

@nicojs There was an issue with the multiprocess appenders not listening to 'error' events (#529).
This has been patched in log4js@6.4.0.

I also read your comments (stryker-mutator/stryker-js#2668 (comment)) suspecting it is due to multiple log4js.configure().

log4js@6.4.0 also supports multiple log4js.configure() (#1113) calls.
Would you like to give it a try?

[nicojs]

Cool! Thanks! Indeed we do multiple calls to .configure. Will try when I have some time

[lamweili]

Be reminded that for multiple .configure() calls, the last configure() call will supersede all prior configurations.
It does not append.

Keep an updated copy of your configuration (which you will keep changing) to pass into the log4js.configure() calls.

Please do get back to us so we can close this issue. Thanks! 🙏

[nicojs]

Thanks for reaching out @peteriman but I think there is a bug in 6.4 having to do with the multiprocess appender. I've boiled it down to a simple example:

Main.js:

// main.js
const childProcess = require("child_process");
const log4js = require("log4js");

log4js.configure({
  appenders: {
    console: {
      type: "stdout",
      layout: {
        pattern: "%[%r (%z) %p %c%] %m",
        type: "pattern",
      },
    },
    server: {
      appender: "console",
      loggerPort: 43291,
      mode: "master",
      type: "multiprocess",
    },
  },
  categories: {
    default: {
      appenders: ["console"],
      level: "info",
    },
  },
});

const logger = log4js.getLogger("main");
logger.info("Start main logging server");

setTimeout(() => {
  const worker = childProcess.fork(require.resolve("./worker.js"), {
    stdio: "inherit",
  });
  worker.on("message", () => {
    console.log("receiving msg");
    setTimeout(() => {
      console.log("killing worker");
      worker.kill();
    }, 1000);
  });
}, 1000);

Worker.js:

// @ts-check
const log4js = require("log4js");

log4js.configure({
  appenders: {
    all: {
      type: "multiprocess",
      mode: "worker",
      loggerPort: 43291,
    },
  },
  categories: {
    default: {
      appenders: ["all"],
      level: "info",
    },
  },
});

const logger = log4js.getLogger("worker");
logger.info("info test");
logger.warn("warn test");
logger.error("error test");

log4js.shutdown((err) => {
  if (err) {
    console.error(err);
  }
  console.log('sending msg')
  process.send("done");
});

Expected (using version 6.2.1):

$ node src/main.js 
23:45:50 (4766) INFO main Start main logging server
23:45:51 (4787) INFO worker info test
23:45:51 (4787) WARN worker warn test
23:45:51 (4787) ERROR worker error test
sending msg
receiving msg
killing worker

Actual:

$ node src/main.js 
23:49:54 (4943) INFO main Start main logging server

Am I doing something obviously wrong?

[nicojs]

Same issue with the default logging config found in the docs (removing loggerHost) :

https://log4js-node.github.io/log4js-node/multiprocess.html

[nicojs]

I found the issue, opening a PR. Also created a separate issue for it: #1161

[lamweili]

Published log4js@6.4.1.

Please verify if it fully resolves your issue and close this accordingly. 🙏

[nicojs]

Our CI pipeline is green. That's all the proof I need :)