log4js.shutdown() not working properly - Error [ERR_STREAM_WRITE_AFTER_END]: write after end #1005

thernstig · 2020-05-05T08:37:57Z

This was first brought up here #788, and I've upgraded to the latest version and the problem still persists.

log4js does not properly write to the file, it seems to close the stream flushing out the latest input, as seen by log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened Error [ERR_STREAM_WRITE_AFTER_END]: write after end.

Code

function handleSignals() {
  // Handle e.g. ctrl+c and other graceful signals to exit
  ['SIGINT', 'SIGTERM'].forEach((signal) =>
    process.on(signal, (code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      shutdown(code);
    })
  );
}

function shutdown(exitCode) {
  process.exitCode = exitCode;
  // Make sure all logs have been written to files, stdout etc.
  log4js.shutdown(() => {
    console.log('### this is printed');
    // This should be removed when we handle graceful shutdown of all services
    process.exit(exitCode);
  });
}

Output

[2020-05-05T10:20:13.893+0200] [INFO] server - Exiting with code: SIGINT. Gracefully cleaning up, please wait...
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/security/projectA-server-audit.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/security/projectA-server-audit.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/security/projectA-server-audit.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:18:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:17:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
### this is printed
npm run start:server exited with code SIGINT

The text was updated successfully, but these errors were encountered:

rnd-debug · 2020-05-05T19:59:23Z

Hello,
are you running log4js in a spawned process?

couldn't reproduce your issue when running log4js "as is".
could reproduce the issue with a simple "file" appender when using log4js from a spawn and defining a non-default handler of SIGINT in the parent process (node v10.16.0):

const express = require('express');
const app = express();
const { spawn } = require('child_process');
app.listen(4000);
const proc = spawn('node', ['logWriter.js'], { // log4js used inside the logWriter
  stdio: 'inherit'
});
process.on('SIGINT', function () {  //causes a double kill
  proc.kill('SIGINT');
});

The handler defined in handleSignals is then called twice.

thernstig · 2020-05-06T08:28:15Z

I am not running it in a spawned process. It does have to do with timing though, so there needs to be some heavy logs outputted whilst pressing Ctrl+c. I can unfortunately not share the entire repo as it is a private project. I'd guess the best way to actually check this is the actual source code logic a bit. I am using both a stdout and file appender at the same time (actually, 5 of them at the same time).

rnd-debug · 2020-05-06T18:01:26Z

Can you try run this and see what are the listeners that are set for SIGINT?
Expected output: only one listener, the one defined in handleSignals.

function handleSignals() {
    ['SIGINT', 'SIGTERM'].forEach((signal) =>
      process.on(signal, (code) => {
        logger.info( `Exiting with code: ${code}. Gracefully cleaning up, please wait...` );
        var listeners = process.listeners('SIGINT'); // <= let's track who is listening
        for (var i = 0; i < listeners.length; i++) {
            console.log(listeners[i].toString());
        }
        shutdown(code);
      })
    );
  }

Besides, could reproduce the issue with a console and a file appender (single file), while using log4js in the following loop and double-hitting Ctrl+c . Not sure if this is related.

const buffer = fs.readFileSync('BIGFILE.txt'); // few MBs should be enough
const contents = String(buffer);
setInterval(() => {
    logger.trace(contents);
},1)

thernstig · 2020-06-01T09:14:39Z

@rnd-debug Apologize for replying back so late, I got stuck in a lot of other issues.

It still happens. Here is the output. You can notice the ^C for when I press ctrl+c. I only press it once. It happens very seldom i.e. I have to start/stop my server and press ctrl+c before getting lucky to invoke it.

[2020-06-01T11:09:30.030+0200] [INFO] service - Some log
^C[2020-06-01T11:09:30.044+0200] [INFO] service - Some log
[2020-06-01T11:09:30.045+0200] [INFO] server - Exiting with code: SIGINT. Gracefully cleaning up, please wait...
(code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners('SIGINT'); // <= let's track who is listening
      for (let i = 0; i < listeners.length; i++) {
        console.log(listeners[i].toString());
      }
      shutdown(code);
    }
(code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners('SIGINT'); // <= let's track who is listening
      for (let i = 0; i < listeners.length; i++) {
        console.log(listeners[i].toString());
      }
      shutdown(code);
    }
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/security/projectA-server-audit.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
(code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners('SIGINT'); // <= let's track who is listening
      for (let i = 0; i < listeners.length; i++) {
        console.log(listeners[i].toString());
      }
      shutdown(code);
    }
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/log/projectA-server-config.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
log4js.fileAppender - Writing to file /home/userA/code/projectA/security/projectA-server-audit.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:257:14)
    at RollingFileStream.Writable.write (_stream_writable.js:306:5)
    at RollingFileStream.Writable.end (_stream_writable.js:617:10)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:72:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (/home/userA/code/projectA/server/shutdown.js:21:10)
    at process.<anonymous> (/home/userA/code/projectA/server/signals.js:20:7)
    at process.emit (events.js:223:5) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}
userA@userA-dev ~/code/projectA (log4js) [SIGINT]>

hapvlz · 2020-10-04T01:44:29Z

Well, I've had the same problem.
What I noticed is that the problem happens only if someone is on the website.

I realized that to close the server you need to close all open connections.
Seems close() is not doing it.

Adding this function before http.close() so far works good.
setImmediate(function(){http.emit('close')});

thernstig · 2021-03-22T08:44:25Z

@rnd-debug @nomiddlename hey did this project die out?

nomiddlename · 2021-03-22T23:00:34Z

It's not dead yet, but it's getting obvious to me that I don't really have the time to look after it anymore. I'll put a message up on the readme, and in the slack channel, to see if anyone wants to take it over or at least help out.

richardhinkamp · 2021-06-09T19:00:47Z

I ran into this as well. To reproduce:

const log4js = require("log4js");

log4js.configure({
  appenders: {
    everything: { type: 'file', filename: 'all-the-logs.log' }
  },
  categories: {
    default: { appenders: [ 'everything' ], level: 'debug' }
  }
});

const logger = log4js.getLogger();
logger.debug('I will be logged in all-the-logs.log');

log4js.shutdown(() => console.log('shutdown 1'));
log4js.shutdown(() => console.log('shutdown 2'));

The issue is the double shutdown() call. In my case the second shutdown was called from an unhandled promise rejection after the first shutdown. This will call the shutdown() from the file appender which will do writer.end('', 'utf-8', complete); and the second shutdown() will write after end. This can be fixed by checking for https://nodejs.org/api/stream.html#stream_writable_writableended but that requires node 12.9.0+

thernstig · 2021-06-09T19:32:32Z

It's not dead yet, but it's getting obvious to me that I don't really have the time to look after it anymore. I'll put a message up on the readme, and in the slack channel, to see if anyone wants to take it over or at least help out.

Did you get anyone to take over as a new project lead?

thernstig · 2021-06-09T19:34:13Z

@richardhinkamp is that the exact same issue? From your description, it does not seem like it. In your case you seem to call log4js.shutdown() twice, which is not done in our case.

richardhinkamp · 2021-06-09T19:53:26Z

Well it gets to the shutdown() in file.js end does an end() after it has already been ended. As I said, my case was not calling shutdown() twice, but calling shutdown() and after that an unhandled promise rejection which called shutdown() as well. So in my case it was not obvious at first that a double shutdown() had been called.

thernstig · 2021-06-09T20:11:38Z

Still, is it the same case as mine? I am curious because the PR says it fixes this issue here, which I am not entirely sure it does. Even though you do not manually call shutdown() twice, in effect it still does that in your case?

richardhinkamp · 2021-06-10T07:25:32Z

Hmm looking into the code some more and there are two places where the stream is ended. In shutdown() but also in reopen(), which will be triggered from a SIGHUP, but that one creates a new stream, so that should not result in a ERR_STREAM_WRITE_AFTER_END. So it might be a separate issue, but you need to dig into this. The handling of SIGINT is logged correctly to the console, does it also log to the log file? If that is the case, there might be another signal after the SIGINT, another SIGINT or a SIGTERM, causing another shutdown call. That one won't be logged, since the the shutdown() already disabled all logging. Maybe adding a console.log(`Exiting with code: ${code}. Gracefully cleaning up, please wait...`) will show what is really happening?

The real problem is that writer.end() is called without checking if it's already ended. To check this with writableEnded node 12.9.0 would be required minimal version, otherwise using the finish event might be used to track if it's ended? I don't know if log4js is willing to drop node 8.

thernstig · 2021-06-10T08:08:27Z

@richardhinkamp the problem I am having is that you are marking this issue as fixed in your PR. So if you mark it as fixed, you will have to make sure it actually fixes this issue and not some other issue you are having. My time is not enough to dig into this code unfortunately, especially with the maintainer being absent for over a year.

richardhinkamp · 2021-06-10T08:12:55Z

@thernstig I have updated the comment in the PR since this may not fix this.

lamweili · 2021-12-30T10:00:35Z

Hi @thernstig, I read your reply to @rnd-debug.

I noticed that the following logs were written 3 times.
Twice immediately after Ctrl+C and the third time somewhere in the middle.

(code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners('SIGINT'); // <= let's track who is listening
      for (let i = 0; i < listeners.length; i++) {
        console.log(listeners[i].toString());
      }
      shutdown(code);
    }

Referencing @rnd-debug's code snippet below, it is possible that the shutdown(code) was executed multiple times in parallel.
Within your original shutdown(code) function, it calls log4js.shutdown().
So there is a possibility that it might be the same issue as @richardhinkamp of calling log4js.shutdown() twice.

function handleSignals() {
    ['SIGINT', 'SIGTERM'].forEach((signal) =>
      process.on(signal, (code) => {
        logger.info( `Exiting with code: ${code}. Gracefully cleaning up, please wait...` );
        var listeners = process.listeners('SIGINT'); // <= let's track who is listening
        for (var i = 0; i < listeners.length; i++) {
            console.log(listeners[i].toString());
        }
        shutdown(code);
      })
    );
  }

From the 3 times occurrence of the logs, it could have been caused by:

multiple SIGINT signals, and/or
duplicated SIGINT listeners

For (1), I understand you only pressed Ctrl+C once, which is indicated by the ^C in your logs.
There might still be a possibility that within the code, it programmatic sends duplicated SIGINT signals.

My main suspicion will be (2). That would explain why the listener logic was printed 3 times.

To ascertain further, can you do me a favor? Use the code below (2 lines changed) and provide the output again.

function handleSignals() {
  ['SIGINT', 'SIGTERM'].forEach((signal) =>
    process.on(signal, (code) => {
      logger.info( `Exiting with code: ${code}. Gracefully cleaning up, please wait...` );
      var listeners = process.listeners(signal); // changed hard-coded 'SIGINT' to signal
      for (var i = 0; i < listeners.length; i++) {
        console.log(signal, `${i}/${listeners.length}`, listeners[i].toString()); // added signal & listeners.length
      }
      shutdown(code);
    })
  );
}

Nevertheless, whichever the case, I agree that log4js should handle them gracefully.

lamweili · 2021-12-30T10:20:24Z

Hi @thernstig and @richardhinkamp,

Let me jump the gun here while waiting for @thernstig's results.

I found the following code sections with reference to lib/appenders/file.js.

  app.shutdown = function (complete) {
    process.removeListener('SIGHUP', app.sighupHandler);
    writer.end('', 'utf-8', complete);
  };

The writer.end() is a function that first writes the final data, closes the stream, and then returns callback upon completion:
https://nodejs.org/api/stream.html#writableendchunk-encoding-callback

During multiple calls of log4js.shutdown(), in which they call app.shutdown() eventually, there is a race condition whereby the second app.shutdown() attempts to write and then close the same stream as the first app.shutdown().

The first attempt might have already written '' and closed the stream. Concurrently, the second attempt to write '' will result in Error [ERR_STREAM_WRITE_AFTER_END]: write after end before it even tries to close it.

Of course, there are other areas in the code that I will not dwell on, such as reopen() which @richardhinkamp has mentioned previously, which might suffer from a similar fate from another signal SIGHUP which is different from the current case of SIGINT. My point is to raise a possible hypothesis for debugging purposes.

I shall wait for @thernstig's results first.
I will submit a PR once the hypothesis is conclusive and a proper fix is done to address the issue.

lamweili · 2022-01-05T16:28:14Z

Hi @thernstig,

Regardless of multiple SIGINT or duplicated listeners in your codes, I believe log4js should do its part of defensive coding.

As such, I have patched it in PR #1113, by always clearing the appenders when log4js.shutdown() is called.
In that way, subsequent/concurrent log4js.shutdown() calls will not be closing the same resources.

Please help to verify PR #1113 if you can.

thernstig · 2022-01-13T13:47:09Z

@peteriman this is the output from your proposed function:

[2022-01-13T14:41:09.503+0100] [INFO] server - Exiting with code: SIGINT. Gracefully cleaning up, please wait...
SIGINT 0/1 (code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners(signal); // changed hard-coded 'SIGINT' to signal
      for (let i = 0; i < listeners.length; i++) {
        console.log(
          signal,
          `${i}/${listeners.length}`,
          listeners[i].toString()
        ); // added signal & listeners.length
      }
      shutdown(code);
    }
^CSIGINT 0/1 (code) => {
      logger.info(
        `Exiting with code: ${code}. Gracefully cleaning up, please wait...`
      );
      const listeners = process.listeners(signal); // changed hard-coded 'SIGINT' to signal
      for (let i = 0; i < listeners.length; i++) {
        console.log(
          signal,
          `${i}/${listeners.length}`,
          listeners[i].toString()
        ); // added signal & listeners.length
      }
      shutdown(code);
    }
log4js.fileAppender - Writing to file /home/userA/code/projectA/devenv_temp/log/projectA-server.log, error happened  Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at new NodeError (node:internal/errors:371:5)
    at _write (node:internal/streams/writable:319:11)
    at RollingFileStream.Writable.end (node:internal/streams/writable:609:17)
    at Function.app.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/appenders/file.js:80:12)
    at /home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:59
    at Array.forEach (<anonymous>)
    at Object.shutdown (/home/userA/code/projectA/server/node_modules/log4js/lib/log4js.js:117:44)
    at shutdown (file:///home/userA/code/projectA/server/shutdown.js:24:10)
    at process.<anonymous> (file:///home/userA/code/projectA/server/signals.js:23:7)
    at process.emit (node:events:390:28) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}

In addition @richardhinkamp wrote #1005 (comment):

The real problem is that writer.end() is called without checking if it's already ended. To check this with writableEnded node 12.9.0 would be required minimal version, otherwise using the finish event might be used to track if it's ended? I don't know if log4js is willing to drop node 8.

Could it be the case that one should check https://nodejs.org/api/stream.html#writablewritableended or similar. Since Node.js 10 is EOL I wonder if @nomiddlename would be ok to bump the supported version to version 12.

lamweili · 2022-01-13T19:09:13Z

@thernstig From the logs, your SIGINT has only 1 listener, no duplicates, which is good.
It does seem that the SIGINT signal was emitted twice, hence triggering the SIGINT listeners twice.

With that, it calls log4js.shutdown() twice, resulting in the race condition I mentioned in my earlier posts.

We could bump it up to Node.js 12, but the fact remains that log4js.shutdown() does not clear its appenders when called.
So despite having the writableEnded API, there are still calls to loop through the same appenders over again with multiple log4js.shutdown() calls, while no errors.

The general gist of PR #1113 is that on entry of log4js.shutdown(), it clones the existing appenders to memory and clears them right away, then proceeding to close the in-memory-appenders. Thus, when the next log4js.shutdown() is called, there is no available appender to close, which should be the case. It addressed the concerns of held up appenders/resources as well.

Did you have a chance to try out PR #1113, which resets those appenders?
Copy and override with the 3 files, run the code again, and let me know your findings:

lib/appenders/index.js
lib/categories.js
lib/log4js.js

thernstig · 2022-01-16T10:51:10Z

@peteriman I think your logic for all of this is sound, so no objection there. But I am still having a very hard time reproducing this. I cannot even reproduce what I posted in #1005 (comment) now when I try.

In my test here you can see ^C being pressed after the first sigint. Since I do not still have the console output for that, it might have been that I in that test pressed ^C twice (once also before the first line in the output I pasted). If that is true, then it makes sense the SIGINT hander was called twice. (And I am 100% certain we do not call it anywhere else in-code or somewhere else in this test so that is the most likely explanation). My bad on not looking closer when I got that output. 😞

Nevertheless, I cannot really re-create this now when I try. I did not test your changes since I could not even reproduce it again without them.

How about we merge your changes, I updated, and if I ever see any problem again I report back?

In that regard, I am fine to close this issue. And good job @peteriman, you're a standup guy and I appreciate you being very clear and verbose in your comments, keep that up! 👍

lamweili · 2022-01-16T14:23:24Z

@thernstig Sure thing! Thanks for your affirmation, makes me feel what I do is worth the effort! 👍

lamweili · 2022-01-19T18:41:50Z

@thernstig I have released it in log4js@6.4.0. Do come back to if the issue persists. Thanks!

richardhinkamp mentioned this issue Jun 9, 2021

fix: handle double shutdown() #1083

Closed

lamweili mentioned this issue Jan 4, 2022

Fixes file descriptor leak in certain use cases #1113

Merged

lamweili closed this as completed in #1113 Jan 17, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log4js.shutdown() not working properly - Error [ERR_STREAM_WRITE_AFTER_END]: write after end #1005

log4js.shutdown() not working properly - Error [ERR_STREAM_WRITE_AFTER_END]: write after end #1005

thernstig commented May 5, 2020

rnd-debug commented May 5, 2020 •

edited

thernstig commented May 6, 2020 •

edited

rnd-debug commented May 6, 2020 •

edited

thernstig commented Jun 1, 2020 •

edited

hapvlz commented Oct 4, 2020 •

edited

thernstig commented Mar 22, 2021

nomiddlename commented Mar 22, 2021

richardhinkamp commented Jun 9, 2021

thernstig commented Jun 9, 2021

thernstig commented Jun 9, 2021

richardhinkamp commented Jun 9, 2021

thernstig commented Jun 9, 2021

richardhinkamp commented Jun 10, 2021

thernstig commented Jun 10, 2021

richardhinkamp commented Jun 10, 2021

lamweili commented Dec 30, 2021 •

edited

lamweili commented Dec 30, 2021 •

edited

lamweili commented Jan 5, 2022

thernstig commented Jan 13, 2022

lamweili commented Jan 13, 2022 •

edited

thernstig commented Jan 16, 2022

lamweili commented Jan 16, 2022

lamweili commented Jan 19, 2022

log4js.shutdown() not working properly - Error [ERR_STREAM_WRITE_AFTER_END]: write after end #1005

log4js.shutdown() not working properly - Error [ERR_STREAM_WRITE_AFTER_END]: write after end #1005

Comments

thernstig commented May 5, 2020

rnd-debug commented May 5, 2020 • edited

thernstig commented May 6, 2020 • edited

rnd-debug commented May 6, 2020 • edited

thernstig commented Jun 1, 2020 • edited

hapvlz commented Oct 4, 2020 • edited

thernstig commented Mar 22, 2021

nomiddlename commented Mar 22, 2021

richardhinkamp commented Jun 9, 2021

thernstig commented Jun 9, 2021

thernstig commented Jun 9, 2021

richardhinkamp commented Jun 9, 2021

thernstig commented Jun 9, 2021

richardhinkamp commented Jun 10, 2021

thernstig commented Jun 10, 2021

richardhinkamp commented Jun 10, 2021

lamweili commented Dec 30, 2021 • edited

lamweili commented Dec 30, 2021 • edited

lamweili commented Jan 5, 2022

thernstig commented Jan 13, 2022

lamweili commented Jan 13, 2022 • edited

thernstig commented Jan 16, 2022

lamweili commented Jan 16, 2022

lamweili commented Jan 19, 2022

rnd-debug commented May 5, 2020 •

edited

thernstig commented May 6, 2020 •

edited

rnd-debug commented May 6, 2020 •

edited

thernstig commented Jun 1, 2020 •

edited

hapvlz commented Oct 4, 2020 •

edited

lamweili commented Dec 30, 2021 •

edited

lamweili commented Dec 30, 2021 •

edited

lamweili commented Jan 13, 2022 •

edited