ENOENT Exception from Daily Rotate File about winston-daily-rotate-file

[mattberther]

Thanks for your report @rgmembreno. Ive encountered this sporadically - but have been unable to reproduce. Id love to get to the bottom of this as well. Do you have consistent steps to reproduce?

[rgmembreno]

Hi Matt,

To reproduce this issue you need to set the 'maxSize' FileTransportOps property to something really small. All I had to do was set it to 65 and let my unit tests run and the error will occur. It seems that the error occurs in version 0.8.0 because DailyRotateFile is trying to delete a file that it has already deleted (the original server.log, for example)

[mattberther]

Thanks @rgmembreno. Im looking at this and will update this ticket as I learn more.

[rdpoor]

+1. This is crashing our server as well. I'm running winston-2.2.0.

[mattberther]

@rdpoor and @rgmembreno - Im having a tough time coming up with a simple example that reproduces this. Can you create a gist that demonstrates the failure?

Thanks!

[rdpoor]

@mattberther -- I've poked at it with a desultory stick and have not been able coax it to reproduce in captivity. At the very least, I'll grab a stack trace next time it happens and see if that offers any insights.

[mattberther]

Thanks @rdpoor - I've tried running this in a real tight loop and haven't been successful either.

[rdpoor]

@mattberther -- do check out winstonjs/winston#800 because @nikdunn spells out some theories on the source of the bug. I'm not clear whether this is a daily rotate file issue or a core issue, but I am NOT using any timed rotation features.

See also winstonjs/winston#768 and winstonjs/winston#867 -- they're probably duplicates.

[rdpoor]

Here's a tiny bit more info. I'm running winston 2.1.1 on node 4.4.4 . In the most recent test, I cleared out the logs directory before running my app -- it ran for about three hours before crashing.

error: uncaughtException: ENOENT: no such file or directory, open '/Users/r/Projects/microservices/logs/5x00.log' date=Tue Jun 21 2016 01:06:27 GMT-0700 (PDT), pid=82080, uid=503, gid=20, cwd=/Users/r/Projects/microservices, execPath=/usr/local/bin/node, version=v4.4.4, argv=[/usr/local/bin/node, /Users/r/Projects/microservices/server.js], rss=50614272, heapTotal=30141024, heapUsed=24508112, loadavg=[2.43994140625, 2.28564453125, 2.49462890625], uptime=2284126
Error: ENOENT: no such file or directory, open '/Users/r/Projects/microservices/logs/5x00.log'
at Error (native)

And the log directory:

-rw-r--r--   1 r  staff      0 Jun 21 01:06 5x00.log.gz
-rw-r--r--   1 r  staff   4842 Jun 21 00:43 5x001.log.gz
-rw-r--r--   1 r  staff   4847 Jun 21 00:20 5x002.log.gz
-rw-r--r--   1 r  staff   6313 Jun 20 23:33 5x003.log.gz
-rw-r--r--   1 r  staff   4794 Jun 20 22:02 5x004.log.gz
-rw-r--r--   1 r  staff  66821 Jun 21 01:06 exception.log
-rw-r--r--   1 r  staff   2588 Jun 20 23:13 proxy.log

Note that the zero length file has the same write date as the crash. For reference, here's my config:

'use strict';

var winston = require('winston');
var fs      = require('fs');

var logDir  = fs.existsSync('/logs') ? '/logs/' : __dirname + '/../logs/';

module.exports = function(appName) {
  return new (winston.Logger)({
    transports: [
      new winston.transports.Console({
        name                           : 'console',
        colorize                       : true,
        handleExceptions               : true,
        json                           : false,
        humanReadableUnhandledException: true
      }),
      new winston.transports.File({
        filename     : logDir + appName + '.log',
        tailable     : true,
        zippedArchive: true,
        maxsize      : 102400,
        maxFiles     : 30,
        colorize     : true
      })
    ],
    exceptionHandlers: [
      new winston.transports.File({
        filename     : logDir + 'exception.log',
        tailable     : true,
        zippedArchive: true,
        maxsize      : 102400,
        maxFiles     : 30,
        colorize     : true
      })
    ]
  });
};

[md2k]

I can put my 5 cents on the issue, but actually i faced with it while i'm use my application in cluster mode.
Whenever rotation is triggered all processes trying to unlink same file, so one of processes do it, rest hang with error:

Error: ENOENT, no such file or directory 'logs/xxxxx_server.log.2016-07-08'
    at Error (native)
    at Object.fs.unlinkSync (fs.js:883:18)
    at DailyRotateFile._getFile (/.../node_modules/winston-daily-rotate-file/index.js:584:12)
    at /.../node_modules/winston-daily-rotate-file/index.js:547:31
    at FSReqWrap.oncomplete (fs.js:95:15)

Here is my patch, not perfect, but at least it work as it should and now i not have any issues with rotation

--- ./node_modules/winston-daily-rotate-file/index-orig.js  2016-07-08 10:36:16.906038200 +0200
+++ ./node_modules/winston-daily-rotate-file/index.js   2016-07-08 10:38:19.389934888 +0200
@@ -581,9 +581,17 @@
     if (this.maxFiles && (this._created >= (this.maxFiles - 1))) {
       remaining = this._created - (this.maxFiles - 1);
       if (remaining === 0) {
-        fs.unlinkSync(path.join(this.dirname, filename));
+   try {
+       fs.unlinkSync(path.join(this.dirname, filename));
+   } catch (e) {
+       console.log(e)
+   }
       } else {
-        fs.unlinkSync(path.join(this.dirname, filename + '.' + remaining));
+   try {
+           fs.unlinkSync(path.join(this.dirname, filename + '.' + remaining));
+   } catch (e) {
+       console.log(e)
+   }
       }
     }

[mattberther]

@md2k Thanks for your patch. Ive incorporated your change and pushed a new version (1.1.5) to npm.

Im closing this issue for the DailyRotateFile transport. We should probably continue the conversation on the FileTransport at winstonjs/winston#800.