From 3ec9811b5edd22816e46adf477f36dc5b62794af Mon Sep 17 00:00:00 2001 From: John Engler Date: Sat, 5 Apr 2014 15:12:45 -0700 Subject: [PATCH 1/5] Update log4js module to expose a shutdown function. loadAppender will check for a shutdown function exposed by a loaded appender. If present, it will be cached so that the shutdown function can execute it. The intent here is that a Node application would not invoked process.exit until after the log4js shutdown callback returns. --- lib/log4js.js | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/lib/log4js.js b/lib/log4js.js index f89369c..f2677ee 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -56,6 +56,7 @@ var events = require('events') , appenders = {} , loggers = {} , appenderMakers = {} +, appenderShutdowns = {} , defaultConfig = { appenders: [ { type: "console" } @@ -299,24 +300,23 @@ function loadAppender(appender) { appenderModule = require(appender); } module.exports.appenders[appender] = appenderModule.appender.bind(appenderModule); + if (appenderModule.shutdown) { + appenderShutdowns[appender] = appenderModule.shutdown.bind(appenderModule); + } appenderMakers[appender] = appenderModule.configure.bind(appenderModule); } function shutdown(cb) { - var allAppenders = Object.keys(appenders).reduce( + var shutdownFunctions = Object.keys(appenderShutdowns).reduce( function(accum, category) { - return accum.concat(appenders[category]); + return accum.concat(appenderShutdowns[category]); }, []); async.forEach( - allAppenders, - function(appender, done) { - if (appender.shutdown) { - appender.shutdown(done); - } else { - done(); - } + shutdownFunctions, + function(shutdownFn, done) { + shutdownFn(done); }, - function() { process.nextTick(cb); } + cb ); } From 8ca092cdb9fce0b4d22bf5e5a4f42b7a6ca67ff4 Mon Sep 17 00:00:00 2001 From: John Engler Date: Sat, 5 Apr 2014 16:14:56 -0700 Subject: [PATCH 2/5] Removed callback to write, as it is not needed. --- lib/appenders/file.js | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/lib/appenders/file.js b/lib/appenders/file.js index b5b3fc8..a0c2869 100644 --- a/lib/appenders/file.js +++ b/lib/appenders/file.js @@ -62,12 +62,7 @@ function fileAppender (file, layout, logSize, numBackups) { openFiles.push(logFile); return function(loggingEvent) { - logFile.write(layout(loggingEvent) + eol, "utf8", - function() { - // just here to keep the event loop - // open - doesn't work. - return; - }); + logFile.write(layout(loggingEvent) + eol, "utf8"); }; } From 633ed3cddbaef3809cab46ce3c2a15a7a92c01a3 Mon Sep 17 00:00:00 2001 From: John Engler Date: Mon, 7 Apr 2014 19:06:29 -0700 Subject: [PATCH 3/5] Support for disabling log writes on shutdown. Updated logger.js to support disabling all log writes. Updated log4js.js shutdown function to disable log writes. Added tests. Update gitignore to ignore rolling date stream's test output. --- .gitignore | 1 + lib/log4js.js | 21 ++++++++++++++-- lib/logger.js | 21 +++++++++++++++- test/logger-test.js | 26 +++++++++++++++++++- test/logging-test.js | 58 +++++++++++++++++++++++++++++++++++++++++--- 5 files changed, 120 insertions(+), 7 deletions(-) diff --git a/.gitignore b/.gitignore index 279bc30..268c88d 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,4 @@ build node_modules .bob/ test/streams/test-rolling-file-stream* +test/streams/test-rolling-stream-with-existing-files* diff --git a/lib/log4js.js b/lib/log4js.js index f2677ee..be5e2c4 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -50,8 +50,9 @@ var events = require('events') , util = require('util') , layouts = require('./layouts') , levels = require('./levels') -, LoggingEvent = require('./logger').LoggingEvent -, Logger = require('./logger').Logger +, loggerModule = require('./logger') +, LoggingEvent = loggerModule.LoggingEvent +, Logger = loggerModule.Logger , ALL_CATEGORIES = '[all]' , appenders = {} , loggers = {} @@ -306,11 +307,27 @@ function loadAppender(appender) { appenderMakers[appender] = appenderModule.configure.bind(appenderModule); } +/** + * Shutdown all log appenders. This will first disable all writing to appenders + * and then call the shutdown function each appender. + * + * @params {Function} cb - The callback to be invoked once all appenders have + * shutdown. If an error occurs, the callback will be given the error object + * as the first argument. + * @returns {void} + */ function shutdown(cb) { + // First, disable all writing to appenders. This prevents appenders from + // not being able to be drained because of run-away log writes. + loggerModule.disableAllLogWrites(); + + // Next, get all the shutdown functions for appenders as an array. var shutdownFunctions = Object.keys(appenderShutdowns).reduce( function(accum, category) { return accum.concat(appenderShutdowns[category]); }, []); + + // Call each of the shutdown functions. async.forEach( shutdownFunctions, function(shutdownFn, done) { diff --git a/lib/logger.js b/lib/logger.js index 4da0daf..de2b41f 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -4,6 +4,8 @@ var levels = require('./levels') , events = require('events') , DEFAULT_CATEGORY = '[default]'; +var logWritesEnabled = true; + /** * Models a logging event. * @constructor @@ -66,7 +68,7 @@ Logger.prototype.isLevelEnabled = function(otherLevel) { }; Logger.prototype[levelString.toLowerCase()] = function () { - if (this.isLevelEnabled(level)) { + if (logWritesEnabled && this.isLevelEnabled(level)) { var args = Array.prototype.slice.call(arguments); args.unshift(level); Logger.prototype.log.apply(this, args); @@ -75,6 +77,23 @@ Logger.prototype.isLevelEnabled = function(otherLevel) { } ); +/** + * Disable all log writes. + * @returns {void} + */ +function disableAllLogWrites() { + logWritesEnabled = false; +} + +/** + * Enable log writes. + * @returns {void} + */ +function enableAllLogWrites() { + logWritesEnabled = true; +} exports.LoggingEvent = LoggingEvent; exports.Logger = Logger; +exports.disableAllLogWrites = disableAllLogWrites; +exports.enableAllLogWrites = enableAllLogWrites; diff --git a/test/logger-test.js b/test/logger-test.js index 55899f2..0bd29e1 100644 --- a/test/logger-test.js +++ b/test/logger-test.js @@ -2,7 +2,8 @@ var vows = require('vows') , assert = require('assert') , levels = require('../lib/levels') -, Logger = require('../lib/logger').Logger; +, loggerModule = require('../lib/logger') +, Logger = loggerModule.Logger; vows.describe('../lib/logger').addBatch({ 'constructor with no parameters': { @@ -53,5 +54,28 @@ vows.describe('../lib/logger').addBatch({ assert.isTrue(logger.isErrorEnabled()); assert.isTrue(logger.isFatalEnabled()); } + }, + + 'should emit log events': { + topic: function() { + var events = [], + logger = new Logger(); + logger.addListener('log', function (logEvent) { events.push(logEvent); }); + logger.debug('Event 1'); + loggerModule.disableAllLogWrites(); + logger.debug('Event 2'); + loggerModule.enableAllLogWrites(); + logger.debug('Event 3'); + return events; + }, + + 'when log writes are enabled': function(events) { + assert.equal(events[0].data[0], 'Event 1'); + }, + + 'but not when log writes are disabled': function(events) { + assert.equal(events.length, 2); + assert.equal(events[1].data[0], 'Event 3'); + } } }).exportTo(module); diff --git a/test/logging-test.js b/test/logging-test.js index 32ff099..a62de31 100644 --- a/test/logging-test.js +++ b/test/logging-test.js @@ -75,13 +75,65 @@ vows.describe('log4js').addBatch({ assert.equal(events[1].level.toString(), 'WARN'); }, - 'should include the error if passed in': function (events) { + '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!'); } - + } + }, + + 'when shutdown is called': { + topic: function() { + var events = { + appenderShutdownCalled: false, + shutdownCallbackCalled: false + }, + log4js = sandbox.require( + '../lib/log4js', + { + requires: { + './appenders/file': + { + name: "file", + appender: function() {}, + configure: function(configuration) { + return function() {}; + }, + shutdown: function(cb) { + events.appenderShutdownCalled = true; + cb(); + } + } + } + } + ), + shutdownCallback = function() { + events.shutdownCallbackCalled = true; + }, + config = { appenders: + [ { "type" : "file", + "filename" : "cheesy-wotsits.log", + "maxLogSize" : 1024, + "backups" : 3 + } + ] + }; + + log4js.configure(config); + log4js.shutdown(shutdownCallback); + // Re-enable log writing so other tests that use logger are not + // affected. + require('../lib/logger').enableAllLogWrites(); + return events; }, - + + 'should invoke appender shutdowns': function(events) { + assert.ok(events.appenderShutdownCalled); + }, + + 'should call callback': function(events) { + assert.ok(events.shutdownCallbackCalled); + } }, 'invalid configuration': { From 3b5eb28115606cbcc3199f678ef45c64ae4d9ed9 Mon Sep 17 00:00:00 2001 From: John Engler Date: Tue, 8 Apr 2014 10:47:18 -0700 Subject: [PATCH 4/5] Update dateFile EOL usage to be consistent with appender. From the looks of the Travis CI failure, this could be the issue causing failures. Not sure as I can't reproduce locally. However, it is still an inconsistency and worth fixing. --- test/dateFileAppender-test.js | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/test/dateFileAppender-test.js b/test/dateFileAppender-test.js index 59355e2..3c61c70 100644 --- a/test/dateFileAppender-test.js +++ b/test/dateFileAppender-test.js @@ -4,7 +4,8 @@ var vows = require('vows') , path = require('path') , fs = require('fs') , sandbox = require('sandboxed-module') -, log4js = require('../lib/log4js'); +, log4js = require('../lib/log4js') +, EOL = require('os').EOL || '\n'; function removeFile(filename) { return function() { @@ -134,7 +135,7 @@ vows.describe('../lib/appenders/dateFile').addBatch({ teardown: removeFile('date-file-test.log'), 'should load appender configuration from a json file': function(err, contents) { - assert.include(contents, 'this should be written to the file' + require('os').EOL); + assert.include(contents, 'this should be written to the file' + EOL); assert.equal(contents.indexOf('this should not be written to the file'), -1); } }, @@ -161,7 +162,7 @@ vows.describe('../lib/appenders/dateFile').addBatch({ , thisTime = format.asString(options.appenders[0].pattern, new Date()); fs.writeFileSync( path.join(__dirname, 'date-file-test' + thisTime), - "this is existing data" + require('os').EOL, + "this is existing data" + EOL, 'utf8' ); log4js.clearAppenders(); From 6e3da6f44ba07fbf29339c365d46d39154a88c30 Mon Sep 17 00:00:00 2001 From: John Engler Date: Tue, 8 Apr 2014 12:40:27 -0700 Subject: [PATCH 5/5] Added error throwing when error loading test file. This will hopefully give us better visibility into our Travis CI build failures. --- test/dateFileAppender-test.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/test/dateFileAppender-test.js b/test/dateFileAppender-test.js index 3c61c70..e64619d 100644 --- a/test/dateFileAppender-test.js +++ b/test/dateFileAppender-test.js @@ -135,6 +135,9 @@ vows.describe('../lib/appenders/dateFile').addBatch({ teardown: removeFile('date-file-test.log'), 'should load appender configuration from a json file': function(err, contents) { + if (err) { + throw err; + } assert.include(contents, 'this should be written to the file' + EOL); assert.equal(contents.indexOf('this should not be written to the file'), -1); }