From 69e64932b1f8e068bca0c5b861c90e9d9d3eade6 Mon Sep 17 00:00:00 2001 From: Daniel Bell Date: Fri, 22 Jul 2011 14:43:33 +1000 Subject: [PATCH] Added functionality to reload configuration file periodically. --- README.md | 5 +- lib/log4js.js | 238 ++++++++++++++++++++++------------- test/logging.js | 329 +++++++++++++++++++++++++++++------------------- 3 files changed, 351 insertions(+), 221 deletions(-) diff --git a/README.md b/README.md index c0ce34a..6d3142e 100644 --- a/README.md +++ b/README.md @@ -52,7 +52,10 @@ Output: You can either configure the appenders and log levels manually (as above), or provide a configuration file (`log4js.configure('path/to/file.json')`) explicitly, or just let log4js look for a file called `log4js.json` (it looks in the current directory first, then the require paths, and finally looks for the default config included in the same directory as the `log4js.js` file). -An example file can be found in `test/log4js.json`. An example config file with log rolling is in `test/with-log-rolling.json` +An example file can be found in `test/log4js.json`. An example config file with log rolling is in `test/with-log-rolling.json`. +By default, the configuration file is checked for changes every 60 seconds, and if changed, reloaded. This allows changes to logging levels +to occur without restarting the application. + You can also pass an object to the configure function, which has the same properties as the json versions. ## connect/express logger diff --git a/lib/log4js.js b/lib/log4js.js index 9efd0a8..4016529 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -56,22 +56,22 @@ var events = require('events') , loggers = {} , appenderMakers = { "file": function(config, fileAppender) { - var layout; - if (config.layout) { - layout = layouts.layout(config.layout.type, config.layout); - } - return fileAppender(config.filename, layout, config.maxLogSize, config.backups, config.pollInterval); + var layout; + if (config.layout) { + layout = layouts.layout(config.layout.type, config.layout); + } + return fileAppender(config.filename, layout, config.maxLogSize, config.backups, config.pollInterval); }, "console": function(config, fileAppender, consoleAppender) { - var layout; - if (config.layout) { - layout = layouts.layout(config.layout.type, config.layout); - } - return consoleAppender(layout); + var layout; + if (config.layout) { + layout = layouts.layout(config.layout.type, config.layout); + } + return consoleAppender(layout); }, "logLevelFilter": function(config, fileAppender, consoleAppender) { - var appender = appenderMakers[config.appender.type](config.appender, fileAppender, consoleAppender); - return logLevelFilter(config.level, appender); + var appender = appenderMakers[config.appender.type](config.appender, fileAppender, consoleAppender); + return logLevelFilter(config.level, appender); } }; @@ -85,25 +85,25 @@ function getLogger (categoryName) { // Use default logger if categoryName is not specified or invalid if (!(typeof categoryName == "string")) { - categoryName = DEFAULT_CATEGORY; + categoryName = DEFAULT_CATEGORY; } var appenderList; if (!loggers[categoryName]) { - // Create the logger for this name if it doesn't already exist - loggers[categoryName] = new Logger(categoryName); - if (appenders[categoryName]) { - appenderList = appenders[categoryName]; - appenderList.forEach(function(appender) { - loggers[categoryName].addListener("log", appender); - }); - } - if (appenders[ALL_CATEGORIES]) { - appenderList = appenders[ALL_CATEGORIES]; - appenderList.forEach(function(appender) { - loggers[categoryName].addListener("log", appender); - }); - } + // Create the logger for this name if it doesn't already exist + loggers[categoryName] = new Logger(categoryName); + if (appenders[categoryName]) { + appenderList = appenders[categoryName]; + appenderList.forEach(function(appender) { + loggers[categoryName].addListener("log", appender); + }); + } + if (appenders[ALL_CATEGORIES]) { + appenderList = appenders[ALL_CATEGORIES]; + appenderList.forEach(function(appender) { + loggers[categoryName].addListener("log", appender); + }); + } } return loggers[categoryName]; @@ -116,63 +116,67 @@ function addAppender () { var args = Array.prototype.slice.call(arguments); var appender = args.shift(); if (args.length == 0 || args[0] === undefined) { - args = [ ALL_CATEGORIES ]; + args = [ ALL_CATEGORIES ]; } //argument may already be an array if (Array.isArray(args[0])) { - args = args[0]; + args = args[0]; } args.forEach(function(category) { - if (!appenders[category]) { - appenders[category] = []; - } - appenders[category].push(appender); - - if (category === ALL_CATEGORIES) { - for (var logger in loggers) { - if (loggers.hasOwnProperty(logger)) { - loggers[logger].addListener("log", appender); - } - } - } else if (loggers[category]) { - loggers[category].addListener("log", appender); - } + if (!appenders[category]) { + appenders[category] = []; + } + appenders[category].push(appender); + + if (category === ALL_CATEGORIES) { + for (var logger in loggers) { + if (loggers.hasOwnProperty(logger)) { + loggers[logger].addListener("log", appender); + } + } + } else if (loggers[category]) { + loggers[category].addListener("log", appender); + } }); } function clearAppenders () { appenders = {}; for (var logger in loggers) { - if (loggers.hasOwnProperty(logger)) { - loggers[logger].removeAllListeners("log"); - } + if (loggers.hasOwnProperty(logger)) { + loggers[logger].removeAllListeners("log"); + } } } function configureAppenders(appenderList, fileAppender, consoleAppender) { clearAppenders(); if (appenderList) { - appenderList.forEach(function(appenderConfig) { - var appender = appenderMakers[appenderConfig.type](appenderConfig, fileAppender, consoleAppender); - if (appender) { - addAppender(appender, appenderConfig.category); - } else { - throw new Error("log4js configuration problem for "+sys.inspect(appenderConfig)); - } - }); + appenderList.forEach(function(appenderConfig) { + var appender = appenderMakers[appenderConfig.type](appenderConfig, fileAppender, consoleAppender); + if (appender) { + addAppender(appender, appenderConfig.category); + } else { + throw new Error("log4js configuration problem for "+sys.inspect(appenderConfig)); + } + }); } else { - addAppender(consoleAppender); + addAppender(consoleAppender); } } function configureLevels(levels) { if (levels) { - for (var category in levels) { - if (levels.hasOwnProperty(category)) { - getLogger(category).setLevel(levels[category]); - } - } + for (var category in levels) { + if (levels.hasOwnProperty(category)) { + getLogger(category).setLevel(levels[category]); + } + } + } else { + for (l in loggers) { + loggers[l].setLevel(); + } } } @@ -230,18 +234,18 @@ Logger.prototype.isLevelEnabled = function(otherLevel) { ['Trace','Debug','Info','Warn','Error','Fatal'].forEach( function(levelString) { - var level = levels.toLevel(levelString); - Logger.prototype['is'+levelString+'Enabled'] = function() { - return this.isLevelEnabled(level); - }; + var level = levels.toLevel(levelString); + Logger.prototype['is'+levelString+'Enabled'] = function() { + return this.isLevelEnabled(level); + }; - Logger.prototype[levelString.toLowerCase()] = function () { - if (this.isLevelEnabled(level)) { + Logger.prototype[levelString.toLowerCase()] = function () { + if (this.isLevelEnabled(level)) { var args = Array.prototype.slice.call(arguments); args.unshift(level); Logger.prototype.log.apply(this, args); - } - }; + } + }; } ); @@ -261,9 +265,9 @@ function getDefaultLogger () { function logLevelFilter (levelString, appender) { var level = levels.toLevel(levelString); return function(logEvent) { - if (logEvent.level.isGreaterThanOrEqualTo(level)) { - appender(logEvent); - } + if (logEvent.level.isGreaterThanOrEqualTo(level)) { + appender(logEvent); + } } } @@ -271,7 +275,7 @@ function logLevelFilter (levelString, appender) { function consoleAppender (layout) { layout = layout || layouts.colouredLayout; return function(loggingEvent) { - console._preLog4js_log(layout(loggingEvent)); + console._preLog4js_log(layout(loggingEvent)); }; } @@ -298,7 +302,7 @@ function fileAppender (file, layout, logSize, numBackups, filePollInterval) { }); return function(loggingEvent) { - logFile.write(layout(loggingEvent)+'\n'); + logFile.write(layout(loggingEvent)+'\n'); }; } @@ -343,21 +347,6 @@ function fileExists (filename) { } } -function configure (configurationFileOrObject) { - var config = configurationFileOrObject; - if (typeof(config) === "string") { - config = JSON.parse(fs.readFileSync(config, "utf8")); - } - if (config) { - try { - configureAppenders(config.appenders, fileAppender, consoleAppender); - configureLevels(config.levels); - } catch (e) { - throw new Error("Problem reading log4js config " + sys.inspect(config) + ". Error was \"" + e.message + "\" ("+e.stack+")"); - } - } -} - function findConfiguration() { //add current directory onto the list of configPaths var paths = ['.'].concat(require.paths); @@ -377,6 +366,79 @@ function findConfiguration() { return undefined; } +function loadConfigurationFile(filename) { + filename = filename || findConfiguration(); + if (filename) { + return JSON.parse(fs.readFileSync(filename, "utf8")); + } + return undefined; +} + +function configureOnceOff(config) { + if (config) { + try { + configureAppenders(config.appenders, fileAppender, consoleAppender); + configureLevels(config.levels); + } catch (e) { + throw new Error("Problem reading log4js config " + sys.inspect(config) + ". Error was \"" + e.message + "\" ("+e.stack+")"); + } + } +} + +var configState = {}; + +function reloadConfiguration() { + var filename = configState.filename || findConfiguration(), + mtime; + if (!filename) { + // can't find anything to reload + return; + } + try { + mtime = fs.statSync(filename).mtime; + } catch (e) { + getLogger('log4js').warn('Failed to load configuration file ' + filename); + return; + } + if (configState.lastFilename && configState.lastFilename === filename) { + if (mtime.getTime() > configState.lastMTime.getTime()) { + configState.lastMTime = mtime; + } else { + filename = null; + } + } else { + configState.lastFilename = filename; + configState.lastMTime = mtime; + } + configureOnceOff(loadConfigurationFile(filename)); +} + +function initReloadConfiguration(filename, options) { + if (configState.timerId) { + clearInterval(configState.timerId); + delete configState.timerId; + } + configState.filename = filename; + configState.timerId = setInterval(reloadConfiguration, options.reloadSecs*1000); +} + +function configure (configurationFileOrObject, options) { + var config = configurationFileOrObject; + if (config === undefined || config === null || typeof(config) === 'string') { + options = options || { reloadSecs: 60 }; + if (options.reloadSecs) { + initReloadConfiguration(config, options); + } + configureOnceOff(loadConfigurationFile(config)); + } else { + options = options || {}; + if (options.reloadSecs) { + getLogger('log4js').warn('Ignoring configuration reload parameter for "object" configuration.'); + } + configureOnceOff(config); + } +} + function replaceConsole(logger) { function replaceWith(fn) { return function() { diff --git a/test/logging.js b/test/logging.js index a3084a5..4b2ce3f 100644 --- a/test/logging.js +++ b/test/logging.js @@ -4,82 +4,82 @@ var vows = require('vows') vows.describe('log4js').addBatch({ 'getLogger': { - topic: function() { - var log4js = require('../lib/log4js'); - log4js.clearAppenders(); - var logger = log4js.getLogger('tests'); - logger.setLevel("DEBUG"); - return logger; - }, - - 'should take a category and return a logger': function(logger) { - assert.equal(logger.category, 'tests'); - assert.equal(logger.level.toString(), "DEBUG"); - assert.isFunction(logger.debug); - assert.isFunction(logger.info); - assert.isFunction(logger.warn); - assert.isFunction(logger.error); - assert.isFunction(logger.fatal); - }, - - 'log events' : { - topic: function(logger) { - var events = []; - logger.addListener("log", function (logEvent) { events.push(logEvent); }); - logger.debug("Debug event"); - logger.trace("Trace event 1"); - logger.trace("Trace event 2"); - logger.warn("Warning event"); + topic: function() { + var log4js = require('../lib/log4js'); + log4js.clearAppenders(); + var logger = log4js.getLogger('tests'); + logger.setLevel("DEBUG"); + return logger; + }, + + 'should take a category and return a logger': function(logger) { + assert.equal(logger.category, 'tests'); + assert.equal(logger.level.toString(), "DEBUG"); + assert.isFunction(logger.debug); + assert.isFunction(logger.info); + assert.isFunction(logger.warn); + assert.isFunction(logger.error); + assert.isFunction(logger.fatal); + }, + + 'log events' : { + topic: function(logger) { + var events = []; + logger.addListener("log", function (logEvent) { events.push(logEvent); }); + logger.debug("Debug event"); + logger.trace("Trace event 1"); + logger.trace("Trace event 2"); + logger.warn("Warning event"); logger.error("Aargh!", new Error("Pants are on fire!")); logger.error("Simulated CouchDB problem", { err: 127, cause: "incendiary underwear" }); - return events; - }, + return events; + }, - 'should emit log events': function(events) { - assert.equal(events[0].level.toString(), 'DEBUG'); - assert.equal(events[0].data[0], 'Debug event'); - assert.instanceOf(events[0].startTime, Date); - }, + 'should emit log events': function(events) { + assert.equal(events[0].level.toString(), 'DEBUG'); + assert.equal(events[0].data[0], 'Debug event'); + assert.instanceOf(events[0].startTime, Date); + }, - 'should not emit events of a lower level': function(events) { - assert.length(events, 4); - assert.equal(events[1].level.toString(), 'WARN'); - }, + 'should not emit events of a lower level': function(events) { + assert.length(events, 4); + assert.equal(events[1].level.toString(), 'WARN'); + }, 'should include the error if passed in': function (events) { assert.instanceOf(events[2].data[1], Error); assert.equal(events[2].data[1].message, 'Pants are on fire!'); } - }, + }, }, 'fileAppender': { - topic: function() { - var appender + topic: function() { + var appender , logmessages = [] , thing = "thing" , fakeFS = { - createWriteStream: function() { - assert.equal(arguments[0], './tmp-tests.log'); - assert.isObject(arguments[1]); - assert.equal(arguments[1].flags, 'a'); + createWriteStream: function() { + assert.equal(arguments[0], './tmp-tests.log'); + assert.isObject(arguments[1]); + assert.equal(arguments[1].flags, 'a'); assert.equal(arguments[1].mode, 0644); assert.equal(arguments[1].encoding, 'utf8'); - return { + return { write: function(message) { logmessages.push(message); } , end: function() {} , destroySoon: function() {} }; - }, + }, watchFile: function() { throw new Error("watchFile should not be called if logSize is not defined"); } - }, - log4js = sandbox.require( + }, + log4js = sandbox.require( '../lib/log4js', { requires: { @@ -87,20 +87,20 @@ vows.describe('log4js').addBatch({ } } ); - log4js.clearAppenders(); + log4js.clearAppenders(); - appender = log4js.fileAppender('./tmp-tests.log', log4js.layouts.messagePassThroughLayout); - log4js.addAppender(appender, 'file-test'); + appender = log4js.fileAppender('./tmp-tests.log', log4js.layouts.messagePassThroughLayout); + log4js.addAppender(appender, 'file-test'); - var logger = log4js.getLogger('file-test'); - logger.debug("this is a test"); + var logger = log4js.getLogger('file-test'); + logger.debug("this is a test"); - return logmessages; - }, - 'should write log messages to file': function(logmessages) { - assert.length(logmessages, 1); - assert.equal(logmessages, "this is a test\n"); - } + return logmessages; + }, + 'should write log messages to file': function(logmessages) { + assert.length(logmessages, 1); + assert.equal(logmessages, "this is a test\n"); + } }, 'fileAppender - with rolling based on size and number of files to keep': { @@ -203,28 +203,28 @@ vows.describe('log4js').addBatch({ }, 'configure' : { - topic: function() { - var messages = {}, fakeFS = { - createWriteStream: function(file) { - return { + topic: function() { + var messages = {}, fakeFS = { + createWriteStream: function(file) { + return { write: function(message) { if (!messages.hasOwnProperty(file)) { - messages[file] = []; - } - messages[file].push(message); + messages[file] = []; + } + messages[file].push(message); } , end: function() {} , destroySoon: function() {} }; - }, - readFileSync: function(file, encoding) { - return require('fs').readFileSync(file, encoding); - }, + }, + readFileSync: function(file, encoding) { + return require('fs').readFileSync(file, encoding); + }, watchFile: function(file) { messages.watchedFile = file; } - }, - log4js = sandbox.require( + }, + log4js = sandbox.require( '../lib/log4js' , { requires: { @@ -232,38 +232,38 @@ vows.describe('log4js').addBatch({ } } ); - return [ log4js, messages ]; - }, - 'should load appender configuration from a json file': function(args) { - var log4js = args[0], messages = args[1]; - delete messages['tmp-tests.log']; - log4js.clearAppenders(); - //this config file defines one file appender (to ./tmp-tests.log) - //and sets the log level for "tests" to WARN - log4js.configure('test/log4js.json'); - var logger = log4js.getLogger("tests"); - logger.info('this should not be written to the file'); - logger.warn('this should be written to the file'); - assert.length(messages['tmp-tests.log'], 1); - assert.equal(messages['tmp-tests.log'][0], 'this should be written to the file\n'); - }, - 'should handle logLevelFilter configuration': function(args) { - var log4js = args[0], messages = args[1]; - delete messages['tmp-tests.log']; - delete messages['tmp-tests-warnings.log']; - log4js.clearAppenders(); - log4js.configure('test/with-logLevelFilter.json'); - var logger = log4js.getLogger("tests"); - logger.info('main'); - logger.error('both'); - logger.warn('both'); - logger.debug('main'); - - assert.length(messages['tmp-tests.log'], 4); - assert.length(messages['tmp-tests-warnings.log'], 2); - assert.deepEqual(messages['tmp-tests.log'], ['main\n','both\n','both\n','main\n']); - assert.deepEqual(messages['tmp-tests-warnings.log'], ['both\n','both\n']); - }, + return [ log4js, messages ]; + }, + 'should load appender configuration from a json file': function(args) { + var log4js = args[0], messages = args[1]; + delete messages['tmp-tests.log']; + log4js.clearAppenders(); + //this config file defines one file appender (to ./tmp-tests.log) + //and sets the log level for "tests" to WARN + log4js.configure('test/log4js.json'); + var logger = log4js.getLogger("tests"); + logger.info('this should not be written to the file'); + logger.warn('this should be written to the file'); + assert.length(messages['tmp-tests.log'], 1); + assert.equal(messages['tmp-tests.log'][0], 'this should be written to the file\n'); + }, + 'should handle logLevelFilter configuration': function(args) { + var log4js = args[0], messages = args[1]; + delete messages['tmp-tests.log']; + delete messages['tmp-tests-warnings.log']; + log4js.clearAppenders(); + log4js.configure('test/with-logLevelFilter.json'); + var logger = log4js.getLogger("tests"); + logger.info('main'); + logger.error('both'); + logger.warn('both'); + logger.debug('main'); + + assert.length(messages['tmp-tests.log'], 4); + assert.length(messages['tmp-tests-warnings.log'], 2); + assert.deepEqual(messages['tmp-tests.log'], ['main\n','both\n','both\n','main\n']); + assert.deepEqual(messages['tmp-tests-warnings.log'], ['both\n','both\n']); + }, 'should handle fileAppender with log rolling' : function(args) { var log4js = args[0], messages = args[1]; delete messages['tmp-test.log']; @@ -271,23 +271,23 @@ vows.describe('log4js').addBatch({ assert.equal(messages.watchedFile, 'tmp-test.log'); }, 'should handle an object or a file name': function(args) { - var log4js = args[0], - messages = args[1], - config = { - "appenders": [ - { - "type" : "file", - "filename" : "cheesy-wotsits.log", - "maxLogSize" : 1024, - "backups" : 3, - "pollInterval" : 15 - } - ] - }; - delete messages['cheesy-wotsits.log']; - log4js.configure(config); - assert.equal(messages.watchedFile, 'cheesy-wotsits.log'); - } + var log4js = args[0], + messages = args[1], + config = { + "appenders": [ + { + "type" : "file", + "filename" : "cheesy-wotsits.log", + "maxLogSize" : 1024, + "backups" : 3, + "pollInterval" : 15 + } + ] + }; + delete messages['cheesy-wotsits.log']; + log4js.configure(config); + assert.equal(messages.watchedFile, 'cheesy-wotsits.log'); + } }, 'with no appenders defined' : { @@ -306,7 +306,7 @@ vows.describe('log4js').addBatch({ } } ); - logger = log4js.getLogger("some-logger"); + logger = log4js.getLogger("some-logger"); logger.debug("This is a test"); return message; }, @@ -428,7 +428,7 @@ vows.describe('log4js').addBatch({ debug: this.log, error: this.log }, - log4js = sandbox.require( + log4js = sandbox.require( '../lib/log4js', { requires: { @@ -440,7 +440,7 @@ vows.describe('log4js').addBatch({ } ); - logger = log4js.getLogger('a-test'); + logger = log4js.getLogger('a-test'); logger.debug("this is a test"); return [ pathsChecked, message, modulePath ]; @@ -535,16 +535,81 @@ vows.describe('log4js').addBatch({ } }, 'configuration persistence' : { - 'should maintain appenders between requires': function () { - var logEvent, firstLog4js = require('../lib/log4js'), secondLog4js; - firstLog4js.clearAppenders(); - firstLog4js.addAppender(function(evt) { logEvent = evt; }); + 'should maintain appenders between requires': function () { + var logEvent, firstLog4js = require('../lib/log4js'), secondLog4js; + firstLog4js.clearAppenders(); + firstLog4js.addAppender(function(evt) { logEvent = evt; }); - secondLog4js = require('../lib/log4js'); - secondLog4js.getLogger().info("This should go to the appender defined in firstLog4js"); + secondLog4js = require('../lib/log4js'); + secondLog4js.getLogger().info("This should go to the appender defined in firstLog4js"); - assert.equal(logEvent.data[0], "This should go to the appender defined in firstLog4js"); - } + assert.equal(logEvent.data[0], "This should go to the appender defined in firstLog4js"); + } + }, + 'configuration reload' : { + topic: function() { + var pathsChecked = [], + messages = [], + logger, + modulePath = require('path').normalize(__dirname + '/../lib/log4js.json'), + fakeFS = { + config: { appenders: [ { type: 'console', layout: { type: 'messagePassThrough' } } ], + levels: { 'a-test' : 'INFO' } }, + readFileSync: function (file, encoding) { + assert.equal(file, modulePath); + assert.equal(encoding, 'utf8'); + return JSON.stringify(fakeFS.config); + }, + statSync: function (path) { + pathsChecked.push(path); + if (path === modulePath) { + return { mtime: new Date() }; + } else { + throw new Error("no such file"); + } + } + }, + fakeConsole = { + log : function (msg) { messages.push(msg); }, + info: this.log, + warn: this.log, + debug: this.log, + error: this.log + }, + setIntervalCallback, + fakeSetInterval = function(cb, timeout) { + setIntervalCallback = cb; + }, + log4js = sandbox.require( + '../lib/log4js', + { + requires: { + 'fs': fakeFS + }, + globals: { + 'console': fakeConsole, + 'setInterval' : fakeSetInterval, + } + } + ); + + logger = log4js.getLogger('a-test'); + logger.info("info1"); + logger.debug("debug2 - should be ignored"); + delete fakeFS.config.levels; + setIntervalCallback(); + logger.info("info3"); + logger.debug("debug4"); + + return [ pathsChecked, messages, modulePath ]; + }, + 'should configure log4js from first log4js.json found': function(args) { + var messages = args[1]; + assert.length(messages, 3); + assert.equal(messages[0], 'info1'); + assert.equal(messages[1], 'info3'); + assert.equal(messages[2], 'debug4'); + } } }).export(module);