Log file is deleted at run time and get operation not permitted error of new generated log file

[hugo048]

When I launch nodejs server and set appenders to write logs to log file, and then I delete the log file at run time, log4js will auto generate a new log file, but I have no permission to read it and it will be deleted when the nodejs server shutdown.
Is there any way to prevent the log file be deleted at run time? or any setting can keep the new generated log file work normally (not to be deleted after nodejs server shutdown.)
Thanks.

[nomiddlename]

My guess is that your node.js server is running with different permissions to your user. If you're using unix then check the umask for the node.js process.

If you can tell me what operating system you're running on, version of log4js, version of node.js and why you're deleting a file that's being written to by log4js, then I might be able to help a bit more.

[hugo048]

Hi @nomiddlename , I run my NodeJS on windows 10 and use log4js v2.4.1, since server might run for long time and someone could delete the log file for no reason, and then this case is happened.
I am confused of I launch the NodeJS server and never stop it, why I have no permission to open new generated log file?
If I can not make it right, does log4js has any way protect the log file which can not be deleted while NodeJS is running?
Thanks.

[yelichi]

Hi @nomiddlename , I have met the same issue, but my scenario was a little bit different. The log file wasn't deleted by me but Log4js itself. I have set a configuration as below. Log4js will 1. compress the log. 2. delete the old one and 3. create a new one. However, after 1 and 2 step finished, it threw "Error: EPERM: operation not permitted, open 'C:\logs\goodLogs.log' " error message. Do you have any idea, how to solve it ? Thanks so much you can help.
{
type: 'file',
filename: 'logs/goodLogs.log',
maxLogSize: 1048576,
backups: 100,
compress: true
}

[rnd-debug]

@yelichi Hello, which version of log4js and node are you using?

[yelichi]

Thanks for your response. My log4js version is 4.5.1, NodeJS version is v8.9.3

[rnd-debug]

@yelichi Can you try to update log4js up to the current?

[yelichi]

Ok, let me try. Thanks.

[yelichi]

I have updated to the latest version of log4js: 6.2.1 The issue is still existed.

[yelichi]

I guess when I write a big object into the log, the object probably needs to be separated into 2 parts, one is in the old log file which will be compressed and deleted, another part will be written to the new log file. The issue should be in the operation for the second part.

[rnd-debug]

Thx for your answers. I wonder if this is not linked to https://nodejs.org/api/path.html#path_windows_vs_posix. Can you also provide the stack trace of the "EPERM" error (interested at which line of log4js the error occures)?

[yelichi]

It didn’t show the stack trace, but fully error as below
log4js.fileAppender - Writing to file logs/goodLogs.log, error happened {Error: EPERM: operation not permitted, open 'C:\logs\goodLogs.log'
errno: -4048,
code: ‘ EPERM’,
syscall: ‘open’,
path: ‘ C:\logs\goodLogs.log’
}

And I checked the source code which is from the path ‘lib/appenders/file.js’, line: 53.
It seems like related to the other dependency module ‘steamroller’.

[Amrf000]

what about this answer? https://stackoverflow.com/questions/52361940/fs-stat-function-for-symlink-pointing-to-directory-in-windows==>finaly,i found my case is caused by someone else's autostart system service that start the same application.

[lamweili]

@yelichi Would you mind trying again with log4js@6.4.2?

I tried the following code snippet and was unable to replicate your issue on Windows.

const log4js = require("log4js");
log4js.configure({
  appenders: {
    console: { type: 'stdout' },
    app: {
      type: 'file',
      filename: 'logs/goodLogs.log',
      maxLogSize: 1, // small size to trigger rollover
      backups: 5,    // total 6 files (1 hot + 5 backups/zip)
      compress: true,
      keepFileExt: true,
    }
  },
  categories: {
    default: { appenders: ['console', 'app'], level: 'all' }
  }
});

const logger = log4js.getLogger();
let count = 1;
let timer = setInterval(() => {
  logger.warn("testing", count);
  if (count >= 10) { // spam 10 times (should have 10 files if not for backups)
   clearInterval(timer)
  }
  count++;
}, 1000);

[lamweili]

@hugo048 I believe your issue is due to the WriteStream handler not being closed.
I am able to replicate using some simple NodeJS codes (not involving log4js).

A short code snippet to demonstrate the differences. Starting node in C:\:

const fs = require("fs");
const path = require("path");
const filePath = "logs/test.log";

// create the parent directory
if (!fs.existsSync(path.dirname(filePath)))
  fs.mkdirSync(path.dirname(filePath));

// create the log file
const writer = fs.createWriteStream(filePath);

// write something and wait callback
writer.write("hello world", () => {
  // read the written data
  console.log(fs.readFileSync(filePath, "utf8")); // hello world

  // delete the file
  fs.unlinkSync(filePath);

  // attempt to read the dir and the file
  console.log(fs.readdirSync(path.dirname(filePath))); // [ 'test.log' ]
  try { fs.readFileSync(filePath, "utf8"); } 
  catch (e) { console.log(e.code); } // EPERM

  // a proper closure or process.exit() will release the held resources
  writer.close(() => {
    // attempt to read the dir and the file
    console.log(fs.readdirSync(path.dirname(filePath))); // [ ]
  });
});

For a file, when a deletion is called and its WriteStream handler is not closed:

• For Linux, the file will be deleted.
• For Windows, NodeJS will hold onto the file.
  • This results in the file being in a "zombie-state" which remains in the folder with no way to open or delete the file.
    
  • Only when the WriteStream handler closes or NodeJS exits, the file is then correctly deleted by Windows.

---

I am quite certain that we close the WriteStream handler before we do any deletion, compression, or movement, at least for log4js@6.4.2 (which is using streamroller@3.0.4). Would you want to try log4js@6.4.2 out?

Nevertheless, this issue will still occur (on Windows) if someone programmatically deletes the particular file when log4js is still holding onto it. It will be resolved on rollover (as it calls WriteStream.end() before creating a new log file).

This issue would also occur (on Windows) in log4js <= 6.3.0 if log4js.configure() is called multiple times. In those versions, when log4js.configure() is called multiple times, multiple handlers are created for the same files without closing. When the last configuration attempts a rollover on the file, it will be blocked as the file handlers from previous configurations are still holding onto the file. In that case, the only effective way would be to exit NodeJS. That was patched in PR #1113 from log4js@^6.4.0.

[yanmofeixi]

this is happening for me as well. maxbackup log # is 1, but it's complaining about unable to delete file for log file log.2

Unhandled Rejection at: Error: EPERM: operation not permitted, stat

'C:\Users\VIVEKT~1\AppData\Local\Temp\cpp.log.2' reason: {}"

@lamweili

[lamweili]

@yanmofeixi When backups=1 (or numBackups=1), log4js will only have the hot file (cpp.log) and the backup (cpp.log.1).

During housekeeping/rollover, log4js will detect matching filenames and delete the excess files.

In this case, as cpp.log.2 wasn't created by this instance of log4js, has stricter permissions, or is currently opened, log4js will not have the permissions to delete it. You have to manually delete it.

By the way, what is your log4js version and do you have the full stacktrace?

[yanmofeixi]

@yanmofeixi When backups=1 (or numBackups=1), log4js will only have the hot file (cpp.log) and the backup (cpp.log.1).

During housekeeping/rollover, log4js will detect matching filenames and delete the excess files.

In this case, as cpp.log.2 wasn't created by this instance of log4js, has stricter permissions, or is currently opened, log4js will not have the permissions to delete it. You have to manually delete it.

By the way, what is your log4js version and do you have the full stacktrace?

I do not see a stack trace, the one posted above is all I have. Also this is only happening on Windows, we are using log4js on linux/mac version of our code and they never ran into a ".log.2" file problem.

I wonder why it's necessary to delete the excess files?

[lamweili]

What is your log4js version and configuration passed into log4js.configure()?

I have no idea how the excess file is created.
There could be a number of reasons and I have listed the two most possible ones below.

1. Unit tests
Someone doing unit-tests on Windows and created cpp.log.2 with escalated permissions that log4js is unable to delete. This wasn't done on the Linux/Mac, the excess file wasn't created and hence no errors.

2. Remnants of a previous misconfiguration:
Someone ran with backups=2 (or numBackup=2) using a userA account on Windows. So the log file would have been created there and then by userA. When it was adjusted back to 1 and ran by another user (say userB), log4js running as userB would not have the permissions to delete cpp.log.2. This wasn't done on the Linux/Mac, the excess file wasn't created and hence no errors.

I ran the code below, with no errors on Windows:

// should be 0 (there should not be existing files as a pre-req, to ensure no remnants)
console.log(fs.readdirSync(".").filter(name => name.startsWith("cpp.")).length);

const log4js = require("log4js");
log4js.configure({
  appenders: {
    out: { type: "stdout" },
    app: { type: "file", filename: "cpp.log", maxLogSize: 1, backups: 1 },
  },
  categories: {
    default: { appenders: ["out", "app"], level: "debug" },
  },
});

// should be 1 (initialised, file created and ready)
console.log(fs.readdirSync(".").filter(name => name.startsWith("cpp.")).length);

const logger = log4js.getLogger();
logger.info("Testing 1");

// should be [ 'cpp.log' ]
fs.readdirSync(".").filter(name => name.startsWith("cpp."));

for (let i = 2; i < 10; i++) {
  logger.info(`Testing ${i}`);
}

// should be [ 'cpp.log', 'cpp.log.1' ]
fs.readdirSync(".").filter(name => name.startsWith("cpp."));

[yanmofeixi]

What is your log4js version and configuration passed into log4js.configure()?

I have no idea how the excess file is created. There could be a number of reasons and I have listed the two most possible ones below.

1. Unit tests Someone doing unit-tests on Windows and created cpp.log.2 with escalated permissions that log4js is unable to delete. This wasn't done on the Linux/Mac, the excess file wasn't created and hence no errors.

2. Remnants of a previous misconfiguration: Someone ran with backups=2 (or numBackup=2) using a userA account on Windows. So the log file would have been created there and then by userA. When it was adjusted back to 1 and ran by another user (say userB), log4js running as userB would not have the permissions to delete cpp.log.2. This wasn't done on the Linux/Mac, the excess file wasn't created and hence no errors.

I ran the code below, with no errors on Windows:

// should be 0 (there should not be existing files as a pre-req, to ensure no remnants)
console.log(fs.readdirSync(".").filter(name => name.startsWith("cpp.")).length);

const log4js = require("log4js");
log4js.configure({
  appenders: {
    out: { type: "stdout" },
    app: { type: "file", filename: "cpp.log", maxLogSize: 1, backups: 1 },
  },
  categories: {
    default: { appenders: ["out", "app"], level: "debug" },
  },
});

// should be 1 (initialised, file created and ready)
console.log(fs.readdirSync(".").filter(name => name.startsWith("cpp.")).length);

const logger = log4js.getLogger();
logger.info("Testing 1");

// should be [ 'cpp.log' ]
fs.readdirSync(".").filter(name => name.startsWith("cpp."));

for (let i = 2; i < 10; i++) {
  logger.info(`Testing ${i}`);
}

// should be [ 'cpp.log', 'cpp.log.1' ]
fs.readdirSync(".").filter(name => name.startsWith("cpp."));

This error does not always happen, that's why I'm scratching my header over how it could happen. So you code very likely will not hit it. And I would say that it's extremely unlikely that someone created a .log.2 file manually, or from a unit test in our use case.

"log4js": "6.2.1"

configuration:
"{"appenders":{"file":{"type":"file","filename":"C:\Users\VIVEKT~1\AppData\Local\Temp\cpp.log","maxLogSize":1048576,"backups":1,"layout":{"type":"pattern","pattern":"%d{ISO8601} %p (pid:2786822) %c - %m"}},"consolestderr":{"type":"console","stderr":true},"fatalFilter":{"type":"logLevelFilter","level":"FATAL","appender":"consolestderr"},"vscodeOutChannel":{"type":{}}},"categories":{"default":{"appenders":["file","fatalFilter","vscodeOutChannel"],"level":"info"}}}"

[lamweili]

@yanmofeixi This is strange as the code I've provided is sort of an unit test and how log4jsis normally used. There shouldn't be any randomness involved.

Unfortunately, it is hard to investigate / fix bugs without a minimal reproduction.

A minimal reproduction allows us to quickly confirm a bug (or point out a coding problem) as well as confirm that we are fixing the right problem.

Often, developers find their own coding problems (non-log4js) while preparing a minimal reproduction.

In any case, you should upgrade to log4js@^6.6.0.