From 7d50c4580187a6747dfa461260ded214d9cf1274 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Mon, 21 Nov 2011 15:03:51 +1100 Subject: [PATCH] Rewrote file appender, fixing issue #16 and issue #31 --- lib/appenders/file.js | 97 ++++++++++++++++++++++++++----------------- log-rolling.js | 11 +++-- test/fileAppender.js | 67 ++++++------------------------ 3 files changed, 77 insertions(+), 98 deletions(-) diff --git a/lib/appenders/file.js b/lib/appenders/file.js index 842ed93..46263ba 100644 --- a/lib/appenders/file.js +++ b/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,18 +86,16 @@ 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; @@ -81,7 +103,6 @@ function fileAppender (file, layout, logSize, numBackups, filePollInterval) { 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"; diff --git a/log-rolling.js b/log-rolling.js index 34c18ce..e77253e 100644 --- a/log-rolling.js +++ b/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); } \ No newline at end of file diff --git a/test/fileAppender.js b/test/fileAppender.js index 92d69eb..72d6e6b 100644 --- a/test/fileAppender.js +++ b/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'); - } - } + } } }