log rotation feature crashes intermittently

[nikdunn]

I have no idea if it is related to the other crash issues I've seen documented, but I am seeing:

Error: ENOENT, open '/work/server/server.log'

Every once in a while. In the directory there is a server.log.gz that is 0 bytes along with other log files that have been successfully rotated.

The issue seems to happen when logging frequency and content is high.

I've handled the uncaught exception, but there's not really anything I can do about it since the logger blew chunks.

I'm doing:

winston.add(winston.transports.File, {
    filename: __dirname + '/server.log',
    json: false,
    colorize: true,
    timestamp: true,
    maxsize: 10000000,
    maxFiles: 50,
    showLevel: true,
    tailable: true,
    zippedArchive: true,
});
winston.remove(winston.transports.Console);

[pose]

Moved here: winstonjs/winston-daily-rotate-file#9

[nikdunn]

Why was this moved? I'm not using that transport. I'm using features in core winston.

[jcrugzz]

Id love to get a reproducible case of this if you can take a stab at it @nikdunn

[nikdunn]

Copied from: #800. One of the tickets should be cancelled.

The problem seems to be a result of the self._archive variable being set to '/work/server/server.log' when the code enters the compressFile() function. See the code here: https://github.com/winstonjs/winston/blob/master/lib/winston/transports/file.js#L468-L530

Usually, when the code executes:
self._stream = fs.createWriteStream(fullname, self.options);
fullname is '/work/server/server.log' and self._archive is '/work/server/server1.log'

So winston opens a new file for writing new log data ('/work/server/server.log') and opens a read stream ('/work/server/server1.log') that gets piped through gzip and to a write stream ('/work/server/server1.log.gz').

I believe the crash occurs when '/work/server/server.log' sneaks through into the compressFile() function.

I think the sequence is:

1. self._stream = fs.createWriteStream(fullname, self.options). This does not wait for the 'open' event to be emitted before,
2. compressFile immediately tries to do fs.createReadStream(String(self._archive)) and in some circumstances the file does not exist yet.

That's my current theory anyway.

My question is: should winston ever gzip '/work/server/server.log'? Is this for the non-tailable log rotation case? Am I on the right track?

Okay fine that was three questions.

[nikdunn]

Follow up...

The problem is caused by two different maxsize tests conflicting with one another.

This line: https://github.com/winstonjs/winston/blob/master/lib/winston/transports/file.js#L371 tests maxsize against (I'm guessing) the number of bytes theoretically written to the file, but not necessarily written to the file. This causes _createStream() to be called.

This test: https://github.com/winstonjs/winston/blob/master/lib/winston/transports/file.js#L540 tests the actual file size of the log file.

I've seen the first test pass, and the second test fail. In that event, createAndFlush() gets called, but _incFile() does not. So createAndFlush attempts to create 'server.log' and reads from it to create 'server.log.gz'

[Vanuan]

I have this too:

Uncaught Error: ENOENT, open 'log/node.log'

[Vanuan]

Should've I created this file manually or what?

[Vanuan]

Maybe there's some racing condition when creating a file?

[nikdunn]

This is fixed. Here is the pull request. #828

[DABH]

Closing this based on #828 but if problems persist in the latest versions of winston (3.1.0 or master), please let us know -- I am doing a bit of digging into 3.x log rotation today anyway. Thanks!