Merge pull request #30 from dbrain/master

hook.io appender

README.md

@@ -2,9 +2,9 @@
 
 NOTE: v0.3.8 of log4js is the last that will work with node versions older than 0.4. To use v0.3.9 you will need node 0.4 or later.
 
-This is a conversion of the [log4js](http://log4js.berlios.de/index.html) 
+This is a conversion of the [log4js](http://log4js.berlios.de/index.html)
 framework to work with [node](http://nodejs.org). I've mainly stripped out the browser-specific code
-and tidied up some of the javascript. It includes a basic file logger, with log rolling based on file size, and also replaces node's console.log functions. 
+and tidied up some of the javascript. It includes a basic file logger, with log rolling based on file size, and also replaces node's console.log functions.
 
 NOTE: in v0.2.x require('log4js') returned a function, and you needed to call that function in your code before you could use it. This was to make testing easier. v0.3.x make use of [felixge's sandbox-module](https://github.com/felixge/node-sandboxed-module), so we don't need to return a function.
 
@@ -14,7 +14,7 @@ npm install log4js
 
 ## tests
 
-Tests now use [vows](http://vowsjs.org), run with `vows test/*.js`. 
+Tests now use [vows](http://vowsjs.org), run with `vows test/*.js`.
 
 ## usage
 
@@ -33,27 +33,27 @@ See example.js:
     var log4js = require('log4js'); //note the need to call the function
     log4js.addAppender(log4js.consoleAppender());
     log4js.addAppender(log4js.fileAppender('logs/cheese.log'), 'cheese');
-    
+
     var logger = log4js.getLogger('cheese');
     logger.setLevel('ERROR');
-    
+
     logger.trace('Entering cheese testing');
     logger.debug('Got cheese.');
-    logger.info('Cheese is Gouda.');  
+    logger.info('Cheese is Gouda.');
     logger.warn('Cheese is quite smelly.');
     logger.error('Cheese is too ripe!');
     logger.fatal('Cheese was breeding ground for listeria.');
-  
+
 Output:
 
     [2010-01-17 11:43:37.987] [ERROR] cheese - Cheese is too ripe!
     [2010-01-17 11:43:37.990] [FATAL] cheese - Cheese was breeding ground for listeria.
 
-  
+
 ## configuration
 
-You can either configure the appenders and log levels manually (as above), or provide a 
+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). 
+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`.
 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.
@@ -75,16 +75,16 @@ You can also pass an object to the configure function, which has the same proper
 
 ## connect/express logger
 
-A connect/express logger has been added to log4js, by [danbell](https://github.com/danbell). This allows connect/express servers to log using log4js. See example-connect-logger.js. 
+A connect/express logger has been added to log4js, by [danbell](https://github.com/danbell). This allows connect/express servers to log using log4js. See example-connect-logger.js.
 
     var log4js = require('./lib/log4js');
     log4js.addAppender(log4js.consoleAppender());
     log4js.addAppender(log4js.fileAppender('cheese.log'), 'cheese');
-      
+
     var logger = log4js.getLogger('cheese');
-    
+
     logger.setLevel('INFO');
-    
+
     var app = require('express').createServer();
     app.configure(function() {
         app.use(log4js.connectLogger(logger, { level: log4js.levels.INFO }));
@@ -100,6 +100,65 @@ The options object that is passed to log4js.connectLogger supports a format stri
         app.use(log4js.connectLogger(logger, { level: log4js.levels.INFO, format: ':method :url' }));
     });
 
+## hook.io logger
+
+A [hook.io](https://github.com/hookio) logger has been added to log4js by [dbrain](https://github.com/dbrain). This allows multiple worker processes to log through a single master process, avoiding issues with rolling etc. in a clustered environment.
+This was mainly created for [cluster](https://github.com/LearnBoost/cluster), but you can adapt the example to match your needs, you know, if it fits them.
+<pre>
+    #### log4js-master.json ####
+    {
+      "appenders": [{
+        "type": "logLevelFilter",
+        "level": "DEBUG",
+        "appender": {
+          "type": "hookio",
+          "name": "hookio-logger",
+          "mode": "master",
+          "debug": false,
+          "appender": {
+            "type": "file",
+            "filename": "muffin.log",
+            "maxLogSize": 104857600,
+            "backups": 10,
+            "pollInterval": 15
+          }
+        }
+      }]
+    }
+
+    #### log4js-worker.json ####
+    {
+      "appenders": [{
+        "type": "logLevelFilter",
+        "level": "DEBUG",
+        "appender": {
+          "type": "hookio",
+          "name": "hookio-logger",
+          "mode": "worker",
+          "debug": false
+        }
+      }]
+    }
+
+    #### ilikebeans.js ####
+    var cluster = require('cluster');
+    var hookCluster = cluster('./doyoulikebeans');
+
+    // Perform the once off configuration depending on type of cluster
+    if (hookCluster.isMaster) {
+      require('log4js').configure('log4js-master.json');
+    } else {
+      require('log4js').configure('log4js-worker.json');
+    }
+
+    // Standard cluster startup
+    hookCluster
+      .use(cluster.logger('run/logs'))
+      .use(cluster.pidfiles('run/pids'))
+      .listen(3000);
+</pre>
+*NOTE* hook.io appender will currently (and probably indefinitely) explode if you enable hook.io debug because of the way log4js overrides console.log
+
 ## author (of this node version)
 
 Gareth Jones (csausdev - gareth.jones@sensis.com.au)
@@ -107,5 +166,5 @@ Gareth Jones (csausdev - gareth.jones@sensis.com.au)
 ## License
 
 The original log4js was distributed under the Apache 2.0 License, and so is this. I've tried to
-keep the original copyright and author credits in place, except in sections that I have rewritten 
+keep the original copyright and author credits in place, except in sections that I have rewritten
 extensively.

lib/appenders/hookio.js

@@ -0,0 +1,56 @@
+var log4js = require('../log4js');
+var layouts = require('../layouts');
+var Hook = require('hook.io').Hook;
+var util = require('util');
+
+var Logger = function createLogger(options) {
+  var self = this;
+  var actualAppender = options.actualAppender;
+  Hook.call(self, options);
+  self.on('hook::ready', function hookReady() {
+    self.on('*::' + options.name + '::log', function log(loggingEvent) {
+      deserializeLoggingEvent(loggingEvent);
+      actualAppender(loggingEvent);
+    });
+  });
+}
+util.inherits(Logger, Hook);
+
+function deserializeLoggingEvent(loggingEvent) {
+  loggingEvent.startTime = new Date(loggingEvent.startTime);
+  loggingEvent.level.toString = function levelToString() {
+    return loggingEvent.level.levelStr;
+  };
+}
+
+function createAppender(hookioOptions, actualAppender) {
+  var loggerHook;
+  if (hookioOptions.mode === 'master') {
+    // Start the master hook, handling the actual logging
+    loggerHook = new Logger({ name: hookioOptions.name, debug: hookioOptions.debug, actualAppender: actualAppender });
+  } else {
+    // Start a worker, just emitting events for a master
+    loggerHook = new Hook({ name: hookioOptions.name, debug: hookioOptions.debug });
+  }
+  loggerHook.start();
+
+  var loggerEvent = hookioOptions.name + '::log';
+  return function log(loggingEvent) {
+    loggerHook.emit(loggerEvent, loggingEvent);
+  };
+}
+
+function configure(config) {
+  var actualAppender;
+  if (config.appender && config.mode === 'master') {
+    log4js.loadAppender(config.appender.type);
+    actualAppender = log4js.appenderMakers[config.appender.type](config.appender);
+  }
+  delete config.appender;
+  delete config.type;
+  return createAppender(config, actualAppender);
+}
+
+exports.name = 'hookio';
+exports.appender = createAppender;
+exports.configure = configure;

lib/appenders/logLevelFilter.js

@@ -1,4 +1,5 @@
 var levels = require('../levels');
+var log4js = require('../log4js');
 
 function logLevelFilter (levelString, appender) {
     var level = levels.toLevel(levelString);
@@ -10,10 +11,11 @@ function logLevelFilter (levelString, appender) {
 }
 
 function configure(config) {
-    var appender = config.makers[config.appender.type](config.appender);
+    log4js.loadAppender(config.appender.type);
+    var appender = log4js.appenderMakers[config.appender.type](config.appender);
     return logLevelFilter(config.level, appender);
 }
 
 exports.name = "logLevelFilter";
 exports.appender = logLevelFilter;
-exports.configure = configure;
+exports.configure = configure;

lib/log4js.js

@@ -136,6 +136,7 @@ function configureAppenders(appenderList) {
     clearAppenders();
     if (appenderList) {
         appenderList.forEach(function(appenderConfig) {
+            loadAppender(appenderConfig.type);
             var appender;
             appenderConfig.makers = appenderMakers;
             appender = appenderMakers[appenderConfig.type](appenderConfig);
@@ -248,13 +249,13 @@ function getDefaultLogger () {
     return getLogger(DEFAULT_CATEGORY);
 }
 
-function findConfiguration() {
+function findConfiguration(filename) {
     var path;
     try {
-        path = require.resolve('log4js.json');
+        path = require.resolve(filename || 'log4js.json');
     } catch (e) {
         //file not found. default to the one in the log4js module.
-        path = __dirname + '/log4js.json';
+        path = filename || __dirname + '/log4js.json';
     }
 
     return path;
@@ -263,8 +264,8 @@ function findConfiguration() {
 var configState = {};
 
 function loadConfigurationFile(filename) {
-    filename = filename || findConfiguration();
+    filename = findConfiguration(filename);
-    if (filename && (!configState.lastFilename || filename !== configState.lastFilename || 
+    if (filename && (!configState.lastFilename || filename !== configState.lastFilename ||
                      !configState.lastMTime || fs.statSync(filename).mtime !== configState.lastMTime)) {
         configState.lastFilename = filename;
         configState.lastMTime = fs.statSync(filename).mtime;
@@ -285,7 +286,7 @@ function configureOnceOff(config) {
 }
 
 function reloadConfiguration() {
-    var filename = configState.filename || findConfiguration(),
+    var filename = findConfiguration(configState.filename),
     mtime;
     if (!filename) {
         // can't find anything to reload
@@ -347,15 +348,10 @@ function replaceConsole(logger) {
     });
 }
 
-function loadAppenders() {
+function loadAppender(appender) {
-    var appenderList = fs.readdirSync(__dirname + '/appenders');
+    var appenderModule = require('./appenders/' + appender);
-    appenderList.forEach(function(file) {
+    module.exports.appenders[appenderModule.name] = appenderModule.appender;
-        if (/\.js$/.test(file)) {
+    appenderMakers[appenderModule.name] = appenderModule.configure;
-            var appenderModule = require('./appenders/' + file);
-            module.exports.appenders[appenderModule.name] = appenderModule.appender;
-            appenderMakers[appenderModule.name] = appenderModule.configure;
-        }
-    });
 }
 
 module.exports = {
@@ -363,6 +359,7 @@ module.exports = {
     getDefaultLogger: getDefaultLogger,
 
     addAppender: addAppender,
+    loadAppender: loadAppender,
     clearAppenders: clearAppenders,
     configure: configure,
 
@@ -371,10 +368,15 @@ module.exports = {
 
     layouts: layouts,
     appenders: {},
+    appenderMakers: appenderMakers,
     connectLogger: require('./connect-logger').connectLogger
 };
 
-loadAppenders();
+//load the old-style appenders
+[ 'console', 'file', 'logLevelFilter' ].forEach(function(appender) {
+   loadAppender(appender);
+});
+
 //set ourselves up if we can find a default log4js.json
 configure(findConfiguration());
 //replace console.log, etc with log4js versions

package.json

@@ -6,23 +6,26 @@
        "logging",
        "log",
        "log4j",
-       "node" 
+       "node"
    ],
    "main": "./lib/log4js",
    "author": "Gareth Jones <gareth.jones@sensis.com.au>",
    "bugs": {
-       "web": "http://github.com/csausdev/log4js-node/issues" 
+       "web": "http://github.com/csausdev/log4js-node/issues"
    },
    "engines": [ "node >=0.4" ],
    "scripts": {
-       "test": "vows test/*.js" 
+       "test": "vows test/*.js"
    },
    "directories": {
        "test": "test",
        "lib": "lib"
    },
+   "dependencies": {
+   },
    "devDependencies": {
        "vows": ">=0.5.2",
-       "sandboxed-module": ">= 0.1.1"
+       "sandboxed-module": ">= 0.1.1",
-   } 
+       "hook.io": "0.7.7"
+   }
 }

test/hookioAppender.js

@@ -0,0 +1,99 @@
+var vows = require('vows');
+var assert = require('assert');
+var sandbox = require('sandboxed-module');
+
+function fancyResultingHookioAppender(opts) {
+  var result = { ons: {}, emissions: {}, logged: [] };
+
+  var fakeLog4Js = {
+    appenderMakers: {}
+  };
+  fakeLog4Js.loadAppender = function (appender) {
+    fakeLog4Js.appenderMakers[appender] = function (config) {
+      result.actualLoggerConfig = config;
+      return function log(logEvent) {
+        result.logged.push(logEvent);
+      }
+    };
+  };
+
+  var fakeHookIo = { Hook: function() { } };
+  fakeHookIo.Hook.prototype.start = function () {
+    result.startCalled = true;
+  };
+  fakeHookIo.Hook.prototype.on = function (eventName, functionToExec) {
+    result.ons[eventName] = { functionToExec: functionToExec };
+    if (eventName === 'hook::ready') {
+      functionToExec();
+    }
+  };
+  fakeHookIo.Hook.prototype.emit = function (eventName, data) {
+    result.emissions[eventName] = result.emissions[eventName] || [];
+    result.emissions[eventName].push({data: data});
+    var on = '*::' + eventName;
+    if (eventName !== 'hook::ready' && result.ons[on]) {
+      result.ons[on].callingCount = result.ons[on].callingCount ? result.ons[on].callingCount += 1 : 1;
+      result.ons[on].functionToExec(data);
+    }
+  };
+
+  return { theResult: result,
+    theModule: sandbox.require('../lib/appenders/hookio', {
+      requires: {
+        '../log4js': fakeLog4Js,
+        'hook.io': fakeHookIo
+      }
+    })
+  };
+}
+
+
+vows.describe('log4js hookioAppender').addBatch({
+  'master': {
+    topic: function() {
+      var fancy = fancyResultingHookioAppender();
+      var logger = fancy.theModule.configure({ name: 'ohno', mode: 'master', appender: { type: 'file' } });
+      logger({ level: { levelStr: 'INFO' }, data: "ALRIGHTY THEN", startTime: '2011-10-27T03:53:16.031Z' });
+      logger({ level: { levelStr: 'DEBUG' }, data: "OH WOW", startTime: '2011-10-27T04:53:16.031Z'});
+      return fancy.theResult;
+    },
+
+    'should write to the actual appender': function (result) {
+      assert.isTrue(result.startCalled);
+      assert.equal(result.logged.length, 2);
+      assert.equal(result.emissions['ohno::log'].length, 2);
+      assert.equal(result.ons['*::ohno::log'].callingCount, 2);
+    },
+
+    'data written should be formatted correctly': function (result) {
+      assert.equal(result.logged[0].level.toString(), 'INFO');
+      assert.equal(result.logged[0].data, 'ALRIGHTY THEN');
+      assert.isTrue(typeof(result.logged[0].startTime) === 'object');
+      assert.equal(result.logged[1].level.toString(), 'DEBUG');
+      assert.equal(result.logged[1].data, 'OH WOW');
+      assert.isTrue(typeof(result.logged[1].startTime) === 'object');
+    },
+
+    'the actual logger should get the right config': function (result) {
+      assert.equal(result.actualLoggerConfig.type, 'file');
+    }
+  },
+  'worker': {
+    'should emit logging events to the master': {
+      topic: function() {
+        var fancy = fancyResultingHookioAppender();
+        var logger = fancy.theModule.configure({ name: 'ohno', mode: 'worker', appender: { type: 'file' } });
+        logger({ level: { levelStr: 'INFO' }, data: "ALRIGHTY THEN", startTime: '2011-10-27T03:53:16.031Z' });
+        logger({ level: { levelStr: 'DEBUG' }, data: "OH WOW", startTime: '2011-10-27T04:53:16.031Z'});
+        return fancy.theResult;
+      },
+
+      'should not write to the actual appender': function (result) {
+        assert.isTrue(result.startCalled);
+        assert.equal(result.logged.length, 0);
+        assert.equal(result.emissions['ohno::log'].length, 2);
+        assert.isUndefined(result.ons['*::ohno::log']);
+      }
+    }
+  }
+}).exportTo(module);

test/logging.js

@@ -69,7 +69,7 @@ vows.describe('log4js').addBatch({
           , log4js = sandbox.require(
               '../lib/log4js'
             , { requires:
-                { './appenders/file.js':
+                { './appenders/file':
                   {
                       name: "file"
                     , appender: function() {}
@@ -123,10 +123,10 @@ vows.describe('log4js').addBatch({
                             });
                         },
                         readdirSync: function() {
-                            return ['file.js'];
+                            return ['file'];
                         }
                     }
-                , './appenders/file.js':
+                , './appenders/file':
                     {
                       name: "file"
                     , appender: function() {}
@@ -168,7 +168,7 @@ vows.describe('log4js').addBatch({
               '../lib/log4js'
             , {
                 requires: {
-                    './appenders/console.js': fakeConsoleAppender
+                    './appenders/console': fakeConsoleAppender
                 }
               }
           );
@@ -303,7 +303,7 @@ vows.describe('log4js').addBatch({
                 {
                     requires: {
                         'fs': fakeFS
-                      , './appenders/console.js': fakeConsole
+                      , './appenders/console': fakeConsole
                     }
                 }
             );
@@ -434,7 +434,7 @@ vows.describe('log4js').addBatch({
                 {
                     requires: {
                         'fs': fakeFS,
-                        './appenders/console.js': fakeConsole
+                        './appenders/console': fakeConsole
                     },
                     globals: {
                         'console': fakeConsole,
@@ -462,7 +462,7 @@ vows.describe('log4js').addBatch({
             assert.equal(logEvents[2].data[0], 'debug4');
         }
     },
-    
+
     'configuration reload with configuration staying the same' : {
         topic: function() {
             var pathsChecked = [],
@@ -494,10 +494,10 @@ vows.describe('log4js').addBatch({
                 }
             },
             fakeConsole = {
-                'name': 'console', 
+                'name': 'console',
                 'appender': function () {
                     return function(evt) { logEvents.push(evt); };
-                }, 
+                },
                 'configure': function (config) {
                     return fakeConsole.appender();
                 }
@@ -510,8 +510,8 @@ vows.describe('log4js').addBatch({
                 '../lib/log4js',
                 {
                     requires: {
-                        'fs': fakeFS, 
+                        'fs': fakeFS,
-                        './appenders/console.js': fakeConsole
+                        './appenders/console': fakeConsole
                     },
                     globals: {
                         'console': fakeConsole,
@@ -538,7 +538,7 @@ vows.describe('log4js').addBatch({
             var logEvents = args[1];
             assert.length(logEvents, 2);
             assert.equal(logEvents[0].data[0], 'info1');
-            assert.equal(logEvents[1].data[0], 'info3'); 
+            assert.equal(logEvents[1].data[0], 'info3');
         }
     }