Rewrote file appender, fixing issue log4js-node#16 and issue log4js-node#31

Author: Gareth Jones

lib/appenders/file.js

@@ -1,4 +1,5 @@
 var layouts = require('../layouts')
+, path = require('path')
 , fs = require('fs');
 
 /**
@@ -8,46 +9,69 @@ var layouts = require('../layouts')
  * @param layout a function that takes a logevent and returns a string (defaults to basicLayout).
  * @param logSize - the maximum size (in bytes) for a log file, if not provided then logs won't be rotated.
  * @param numBackups - the number of log files to keep after logSize has been reached (default 5)
- * @param filePollInterval - the time in seconds between file size checks (default 30s)
  */
-function fileAppender (file, layout, logSize, numBackups, filePollInterval) {
+function fileAppender (file, layout, logSize, numBackups) {
+    var bytesWritten = 0;
+    file = path.normalize(file);
     layout = layout || layouts.basicLayout;
     numBackups = numBackups === undefined ? 5 : numBackups;
     //there has to be at least one backup if logSize has been specified
     numBackups = numBackups === 0 ? 1 : numBackups;
-    filePollInterval = filePollInterval * 1000 || 30000;
 
     function setupLogRolling () {
-        fs.watchFile(
-            file,
-            {
-                persistent: false,
-                interval: filePollInterval
-            },
-            function (curr, prev) {
-                if (curr.size >= logSize) {
-                    rollThatLog();
-                }
+        try {
+            var stat = fs.statSync(file);
+            bytesWritten = stat.size;
+            if (bytesWritten >= logSize) {
+                rollThatLog();
             }
-        );
+        } catch (e) {
+            //file does not exist
+            bytesWritten = 0;
+        }
     }
 
     function rollThatLog () {
-        //roll the backups (rename file.n-1 to file.n, where n <= numBackups)
-        for (var i=numBackups; i > 0; i--) {
-            if (i > 1) {
-                if (fileExists(file + '.' + (i-1))) {
-                    fs.renameSync(file+'.'+(i-1), file+'.'+i);
-                }
+        function index(filename) {
+            return parseInt(filename.substring((path.basename(file) + '.').length), 10) || 0;
+        }
+
+        var nameMatcher = new RegExp('^' + path.basename(file));
+        function justTheLogFiles (item) {
+            return nameMatcher.test(item);
+        }
+
+        function byIndex(a, b) {
+            if (index(a) > index(b)) {
+                return 1;
+            } else if (index(a) < index(b) ) {
+                return -1;
             } else {
-                fs.renameSync(file, file+'.1');
+                return 0;
             }
         }
+
+        function increaseFileIndex (fileToRename) {
+            var idx = index(fileToRename);
+            if (idx < numBackups) {
+                fs.renameSync(path.join(path.dirname(file), fileToRename), file + '.' + (idx + 1));
+            }
+        }
+
+        //roll the backups (rename file.n to file.n+1, where n <= numBackups)
+        fs.readdirSync(path.dirname(file))
+          .filter(justTheLogFiles)
+            .sort(byIndex)
+              .reverse()
+                .forEach(increaseFileIndex);
+
         //let's make a new file
         var newLogFileFD = fs.openSync(file, 'a', 0644)
       , oldLogFileFD = logFile.fd;
         logFile.fd = newLogFileFD;
         fs.close(oldLogFileFD);
+        //reset the counter
+        bytesWritten = 0;
     }
 
     function fileExists (filename) {
@@ -62,26 +86,23 @@ function fileAppender (file, layout, logSize, numBackups, filePollInterval) {
     function openTheStream() {
         var stream = fs.createWriteStream(file, { flags: 'a', mode: 0644, encoding: 'utf8' });
         stream.on("open", function() {
-            canWrite = true;
-            while (logEventBuffer.length > 0 && canWrite) {
-                canWrite = writeToLog(logEventBuffer.shift());
+            if (logEventBuffer.length > 0) {
+                writeToLog(logEventBuffer.shift());
             }
         });
         stream.on("error", function (err) {
-            console.error("log4js.fileAppender - Error happened ", err);
+            console.error("log4js.fileAppender - Writing to file %s, error happened ", file, err);
         });
         stream.on("drain", function() {
-            canWrite = true;
-            while (logEventBuffer.length > 0 && canWrite) {
-                canWrite = writeToLog(logEventBuffer.shift());
+            if (logEventBuffer.length > 0) {
+                writeToLog(logEventBuffer.shift());
             }
         });
         return stream;
     }
 
 
     var logEventBuffer = []
-  , canWrite = false
   , logFile = openTheStream();
 
     if (logSize > 0) {
@@ -95,17 +116,17 @@ function fileAppender (file, layout, logSize, numBackups, filePollInterval) {
     });
 
     function writeToLog(loggingEvent) {
-	return logFile.write(layout(loggingEvent)+'\n', "utf8");
+        var logMessage = layout(loggingEvent)+'\n';
+        //not entirely accurate, but it'll do.
+        bytesWritten += logMessage.length;
+        logFile.write(logMessage, "utf8");
+        if (bytesWritten >= logSize) {
+            rollThatLog();
+        }
     }
 
     return function(loggingEvent) {
-        //because the log stream is opened asynchronously, we don't want to write
-        //until it is ready.
-        if (canWrite) {
-            canWrite = writeToLog(loggingEvent);
-        } else {
-            logEventBuffer.push(loggingEvent);
-        }
+        logEventBuffer.push(loggingEvent);
     };
 }
 
@@ -114,7 +135,7 @@ function configure(config) {
     if (config.layout) {
 	layout = layouts.layout(config.layout.type, config.layout);
     }
-    return fileAppender(config.filename, layout, config.maxLogSize, config.backups, config.pollInterval);
+    return fileAppender(config.filename, layout, config.maxLogSize, config.backups);
 }
 
 exports.name = "file";

log-rolling.js

@@ -3,17 +3,16 @@ var log4js = require('./lib/log4js')
 , i = 0;
 log4js.configure({
   "appenders": [
+      {
+          type: "console"
+        , category: "console"
+      },
       {
           "type": "file",
           "filename": "tmp-test.log",
           "maxLogSize": 1024,
           "backups": 3,
-          "pollInterval": 0.1,
           "category": "test"
-      },
-      {
-          type: "console"
-        , category: "console"
       }
   ]
 });
@@ -23,6 +22,6 @@ function doTheLogging(x) {
     log.info("Logging something %d", x);
 }
 
-for ( ; i < 100000; i++) {
+for ( ; i < 5000; i++) {
     doTheLogging(i);
 }

test/fileAppender.js

@@ -40,17 +40,15 @@ vows.describe('log4js fileAppender').addBatch({
           , that = this;
             remove(testFile);
             remove(testFile + '.1');
-            //log file of 100 bytes maximum, no backups, check every 10ms for changes
-            log4js.addAppender(log4js.fileAppender(testFile, log4js.layouts.basicLayout, 100, 0, 0.01), 'max-file-size');
+            //log file of 100 bytes maximum, no backups
+            log4js.addAppender(log4js.fileAppender(testFile, log4js.layouts.basicLayout, 100, 0), 'max-file-size');
             logger.info("This is the first log message.");
             logger.info("This is an intermediate log message.");
-            //we have to wait before writing the second one, because node is too fast for the file system.
-            setTimeout(function() {
-                logger.info("This is the second log message.");
-            }, 200);
+            logger.info("This is the second log message.");
+            //wait for the file system to catch up
             setTimeout(function() {
                 fs.readFile(testFile, "utf8", that.callback);
-            }, 400);
+            }, 100);
         },
         'log file should only contain the second message': function(err, fileContents) {
             assert.include(fileContents, "This is the second log message.\n");
@@ -75,21 +73,17 @@ vows.describe('log4js fileAppender').addBatch({
             remove(testFile+'.1');
             remove(testFile+'.2');
 
-            //log file of 50 bytes maximum, 2 backups, check every 10ms for changes
-            log4js.addAppender(log4js.fileAppender(testFile, log4js.layouts.basicLayout, 50, 2, 0.01), 'max-file-size-backups');
+            //log file of 50 bytes maximum, 2 backups
+            log4js.addAppender(log4js.fileAppender(testFile, log4js.layouts.basicLayout, 50, 2), 'max-file-size-backups');
             logger.info("This is the first log message.");
-            //we have to wait before writing the second one, because node is too fast for the file system.
+            logger.info("This is the second log message.");
+            logger.info("This is the third log message.");
+            logger.info("This is the fourth log message.");
             var that = this;
+            //give the system a chance to open the stream
             setTimeout(function() {
-                logger.info("This is the second log message.");
-            }, 200);
-            setTimeout(function() {
-                logger.info("This is the third log message.");
-            }, 400);
-            setTimeout(function() {
-                logger.info("This is the fourth log message.");
                 fs.readdir(__dirname, that.callback);
-            }, 600);
+            }, 100);
         },
         'the log files': {
             topic: function(files) {
@@ -146,42 +140,7 @@ vows.describe('log4js fileAppender').addBatch({
 	    'should load appender configuration from a json file': function(err, contents) {
 	        assert.include(contents, 'this should be written to the file\n');
                 assert.equal(contents.indexOf('this should not be written to the file'), -1);
-	    },
-            'and log rolling': {
-                topic: function() {
-                    var sandbox = require('sandboxed-module')
-                  , that = this
-                  , fileAppender = sandbox.require(
-                      '../lib/appenders/file.js'
-                    , { requires:
-                        { 'fs':
-                          {
-                              watchFile: function(filename, options, cb) {
-                                  that.callback(null, filename);
-                              }
-                            , createWriteStream: function() {
-                                  return {
-                                      on: function() {}
-                                    , end: function() {}
-                                    , destroy: function() {}
-                                  };
-                              }
-                          }
-                        }
-                      }
-                    );
-
-                    fileAppender.configure({
-                        filename: "cheese.log"
-                      , maxLogSize: 100
-                      , backups: 5
-                      , pollInterval: 30
-                    });
-                },
-                'should watch the log file': function(watchedFile) {
-                    assert.equal(watchedFile, 'cheese.log');
-                }
-            }
+	    }
         }
     }