0.6.14

fix shutdown method: make sure to callback when write completed immediat...

.gitignore

@@ -4,3 +4,4 @@ build
 node_modules
 .bob/
 test/streams/test-rolling-file-stream*
+test/streams/test-rolling-stream-with-existing-files*

README.md

@@ -1,7 +1,7 @@
 # log4js-node [![Build Status](https://secure.travis-ci.org/nomiddlename/log4js-node.png?branch=master)](http://travis-ci.org/nomiddlename/log4js-node)
 
 
-This is a conversion of the [log4js](http://log4js.berlios.de/index.html)
+This is a conversion of the [log4js](https://github.com/stritti/log4js)
 framework to work with [node](http://nodejs.org). I've mainly stripped out the browser-specific code and tidied up some of the javascript. 
 
 Out of the box it supports the following features:

examples/flush-on-exit.js

@@ -0,0 +1,27 @@
+/**
+ * run this, then "ab -c 10 -n 100 localhost:4444/" to test (in
+ * another shell)
+ */
+var log4js = require('../lib/log4js');
+log4js.configure({
+      appenders: [
+        { type: 'file', filename: 'cheese.log', category: 'cheese' },
+        { type: 'console'}
+  ]
+});
+
+var logger = log4js.getLogger('cheese');
+logger.setLevel('INFO');
+
+var http=require('http');
+
+var server = http.createServer(function(request, response){
+    response.writeHead(200, {'Content-Type': 'text/plain'});
+    var rd = Math.random() * 50;
+    logger.info("hello " + rd);
+    response.write('hello ');
+    if (Math.floor(rd) == 30){
+        log4js.shutdown(function() { process.exit(1); });
+    }
+    response.end();
+}).listen(4444);

lib/appenders/dateFile.js

@@ -1,6 +1,7 @@
 "use strict";
 var streams = require('../streams')
 , layouts = require('../layouts')
+, async = require('async')
 , path = require('path')
 , os = require('os')
 , eol = os.EOL || '\n'
@@ -24,12 +25,12 @@ function appender(filename, pattern, alwaysIncludePattern, layout) {
   layout = layout || layouts.basicLayout;
 
   var logFile = new streams.DateRollingFileStream(
-    filename, 
-    pattern, 
+    filename,
+    pattern,
     { alwaysIncludePattern: alwaysIncludePattern }
   );
   openFiles.push(logFile);
-  
+
   return function(logEvent) {
     logFile.write(layout(logEvent) + eol, "utf8");
   };
@@ -38,15 +39,15 @@ function appender(filename, pattern, alwaysIncludePattern, layout) {
 
 function configure(config, options) {
   var layout;
-  
+
   if (config.layout) {
     layout = layouts.layout(config.layout.type, config.layout);
   }
-  
+
   if (!config.alwaysIncludePattern) {
     config.alwaysIncludePattern = false;
   }
-  
+
   if (options && options.cwd && !config.absolute) {
     config.filename = path.join(options.cwd, config.filename);
   }
@@ -54,5 +55,18 @@ function configure(config, options) {
   return appender(config.filename, config.pattern, config.alwaysIncludePattern, layout);
 }
 
+function shutdown(cb) {
+  async.forEach(openFiles, function(file, done) {
+    if (!file.write(eol, "utf-8")) {
+      file.once('drain', function() {
+        file.end(done);
+      });
+    } else {
+      file.end(done);
+    }
+  }, cb);
+}
+
 exports.appender = appender;
 exports.configure = configure;
+exports.shutdown = shutdown;

lib/appenders/file.js

@@ -1,5 +1,6 @@
 "use strict";
 var layouts = require('../layouts')
+, async = require('async')
 , path = require('path')
 , fs = require('fs')
 , streams = require('../streams')
@@ -78,5 +79,18 @@ function configure(config, options) {
   return fileAppender(config.filename, layout, config.maxLogSize, config.backups);
 }
 
+function shutdown(cb) {
+  async.forEach(openFiles, function(file, done) {
+    if (!file.write(eol, "utf-8")) {
+      file.once('drain', function() {
+        file.end(done);
+      });
+    } else {
+      file.end(done);
+    }
+  }, cb);
+}  
+
 exports.appender = fileAppender;
 exports.configure = configure;
+exports.shutdown = shutdown;

lib/log4js.js

@@ -44,17 +44,20 @@
  * Website: http://log4js.berlios.de
  */
 var events = require('events')
+, async = require('async')
 , fs = require('fs')
 , path = require('path')
 , 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 = {}
 , appenderMakers = {}
+, appenderShutdowns = {}
 , defaultConfig =   {
   appenders: [
     { type: "console" }
@@ -303,9 +306,42 @@ 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);
 }
 
+/**
+ * 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) {
+      shutdownFn(done);
+    },
+		cb
+  );
+}
+
 module.exports = {
   getLogger: getLogger,
   getDefaultLogger: getDefaultLogger,
@@ -315,6 +351,7 @@ module.exports = {
   loadAppender: loadAppender,
   clearAppenders: clearAppenders,
   configure: configure,
+  shutdown: shutdown,
   
   replaceConsole: replaceConsole,
   restoreConsole: restoreConsole,

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
@@ -69,7 +71,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);
@@ -78,6 +80,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;

lib/streams/DateRollingFileStream.js

@@ -17,7 +17,14 @@ function DateRollingFileStream(filename, pattern, options, now) {
   }
   this.pattern = pattern || '.yyyy-MM-dd';
   this.now = now || Date.now;
-  this.lastTimeWeWroteSomething = format.asString(this.pattern, new Date(this.now()));
+
+  if (fs.existsSync(filename)) {
+    var stat = fs.statSync(filename);
+    this.lastTimeWeWroteSomething = format.asString(this.pattern, stat.mtime);
+  } else {
+    this.lastTimeWeWroteSomething = format.asString(this.pattern, new Date(this.now()));
+  }
+
   this.baseFilename = filename;
   this.alwaysIncludePattern = false;
   

package.json

@@ -1,6 +1,6 @@
 {
   "name": "log4js",
-  "version": "0.6.12",
+  "version": "0.6.14",
   "description": "Port of Log4js to work with node.",
   "keywords": [
     "logging",

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,10 @@ 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);
+        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);
       }
     },
@@ -161,7 +165,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();

test/layouts-test.js

@@ -7,7 +7,7 @@ function test(args, pattern, value) {
   var layout = args[0]
   , event = args[1]
   , tokens = args[2];
-  
+
   assert.equal(layout(pattern, tokens)(event), value);
 }
 
@@ -16,7 +16,7 @@ vows.describe('log4js layouts').addBatch({
     topic: function() {
       return require('../lib/layouts').colouredLayout;
     },
-    
+
     'should apply level colour codes to output': function(layout) {
       var output = layout({
         data: ["nonsense"],
@@ -40,7 +40,7 @@ vows.describe('log4js layouts').addBatch({
       assert.equal(output, '\x1B[31m[2010-12-05 14:18:30.045] [ERROR] cheese - \x1B[39mthing 2');
     }
   },
-  
+
   'messagePassThroughLayout': {
     topic: function() {
       return require('../lib/layouts').messagePassThroughLayout;
@@ -58,49 +58,49 @@ vows.describe('log4js layouts').addBatch({
     },
     'should support the console.log format for the message' : function(layout) {
       assert.equal(layout({
-        data: ["thing %d", 1, "cheese"], 
-        startTime: new Date(2010, 11, 5, 14, 18, 30, 45), 
-        categoryName: "cheese", 
+        data: ["thing %d", 1, "cheese"],
+        startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
+        categoryName: "cheese",
         level : {
-          colour: "green", 
+          colour: "green",
           toString: function() { return "ERROR"; }
         }
       }), "thing 1 cheese");
     },
     'should output the first item even if it is not a string': function(layout) {
       assert.equal(layout({
-        data: [ { thing: 1} ], 
-        startTime: new Date(2010, 11, 5, 14, 18, 30, 45), 
-        categoryName: "cheese", 
+        data: [ { thing: 1} ],
+        startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
+        categoryName: "cheese",
         level: {
-          colour: "green", 
+          colour: "green",
           toString: function() { return "ERROR"; }
         }
       }), "{ thing: 1 }");
     },
     'should print the stacks of a passed error objects': function(layout) {
       assert.isArray(layout({
-        data: [ new Error() ], 
-        startTime: new Date(2010, 11, 5, 14, 18, 30, 45), 
-        categoryName: "cheese", 
+        data: [ new Error() ],
+        startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
+        categoryName: "cheese",
         level: {
-          colour: "green", 
+          colour: "green",
           toString: function() { return "ERROR"; }
         }
       }).match(/Error\s+at Object\..*\s+\((.*)test[\\\/]layouts-test\.js\:\d+\:\d+\)\s+at runTest/)
                      , 'regexp did not return a match');
     },
-    'with passed augmented errors': { 
+    'with passed augmented errors': {
       topic: function(layout){
         var e = new Error("My Unique Error Message");
         e.augmented = "My Unique attribute value";
         e.augObj = { at1: "at2" };
         return layout({
-          data: [ e ], 
-          startTime: new Date(2010, 11, 5, 14, 18, 30, 45), 
-          categoryName: "cheese", 
+          data: [ e ],
+          startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
+          categoryName: "cheese",
           level: {
-            colour: "green", 
+            colour: "green",
             toString: function() { return "ERROR"; }
           }
         });
@@ -118,10 +118,10 @@ vows.describe('log4js layouts').addBatch({
         assert.isArray(m);
       }
     }
-    
-    
+
+
   },
-  
+
   'basicLayout': {
     topic: function() {
       var layout = require('../lib/layouts').basicLayout,
@@ -143,17 +143,17 @@ vows.describe('log4js layouts').addBatch({
       var layout = args[0], event = args[1], output, lines,
       error = new Error("Some made-up error"),
       stack = error.stack.split(/\n/);
-      
+
       event.data = ['this is a test', error];
       output = layout(event);
       lines = output.split(/\n/);
-      
+
       assert.equal(lines.length - 1, stack.length);
       assert.equal(
-        lines[0], 
+        lines[0],
         "[2010-12-05 14:18:30.045] [DEBUG] tests - this is a test [Error: Some made-up error]"
       );
-      
+
       for (var i = 1; i < stack.length; i++) {
         assert.equal(lines[i+2], stack[i+1]);
       }
@@ -166,13 +166,13 @@ vows.describe('log4js layouts').addBatch({
       }];
       output = layout(event);
       assert.equal(
-        output, 
-        "[2010-12-05 14:18:30.045] [DEBUG] tests - this is a test " + 
+        output,
+        "[2010-12-05 14:18:30.045] [DEBUG] tests - this is a test " +
           "{ name: 'Cheese', message: 'Gorgonzola smells.' }"
       );
     }
   },
-  
+
   'patternLayout': {
     topic: function() {
       var event = {
@@ -188,9 +188,12 @@ vows.describe('log4js layouts').addBatch({
         testFunction: function() { return 'testFunctionToken'; },
         fnThatUsesLogEvent: function(logEvent) { return logEvent.level.toString(); }
       };
+
+      //override getTimezoneOffset
+      event.startTime.getTimezoneOffset = function() { return 0; };
       return [layout, event, tokens];
     },
-    
+
     'should default to "time logLevel loggerName - message"': function(args) {
       test(args, null, "14:18:30 DEBUG multiple.levels.of.tests - this is a test\n");
     },

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);

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': {