0.6.9

Added logic to serialize Error objects correctly

lib/appenders/categoryFilter.js

@@ -0,0 +1,20 @@
+"use strict";
+var log4js = require('../log4js');
+
+function categoryFilter (excludes, appender) {
+  if (typeof(excludes) === 'string') excludes = [excludes];
+  return function(logEvent) {
+    if (excludes.indexOf(logEvent.categoryName) === -1) {
+      appender(logEvent);
+    }
+  };
+}
+
+function configure(config) {
+  log4js.loadAppender(config.appender.type);
+  var appender = log4js.appenderMakers[config.appender.type](config.appender);
+  return categoryFilter(config.exclude, appender);
+}
+
+exports.appender = categoryFilter;
+exports.configure = configure;

lib/appenders/clustered.js

@@ -0,0 +1,126 @@
+"use strict";
+
+var cluster = require('cluster');
+var log4js = require('../log4js');
+
+/**
+ * Takes a loggingEvent object, returns string representation of it.
+ */
+function serializeLoggingEvent(loggingEvent) {
+	// JSON.stringify(new Error('test')) returns {}, which is not really useful for us.
+	// The following allows us to serialize errors correctly.
+	for (var i = 0; i < loggingEvent.data.length; i++) {
+		var item = loggingEvent.data[i];
+		if (item && item.stack && JSON.stringify(item) === '{}') { // Validate that we really are in this case
+			loggingEvent.data[i] = {stack : item.stack};
+		}
+	}
+	return JSON.stringify(loggingEvent);
+}
+
+/**
+ * Takes a string, returns an object with
+ * the correct log properties.
+ *
+ * This method has been "borrowed" from the `multiprocess` appender 
+ * by `nomiddlename` (https://github.com/nomiddlename/log4js-node/blob/master/lib/appenders/multiprocess.js)
+ *
+ * Apparently, node.js serializes everything to strings when using `process.send()`, 
+ * so we need smart deserialization that will recreate log date and level for further processing by log4js internals.
+ */
+function deserializeLoggingEvent(loggingEventString) {
+
+	var loggingEvent;
+	
+	try {
+	
+		loggingEvent = JSON.parse(loggingEventString);
+		loggingEvent.startTime = new Date(loggingEvent.startTime);
+		loggingEvent.level = log4js.levels.toLevel(loggingEvent.level.levelStr);
+		
+	} catch (e) {
+		
+		// JSON.parse failed, just log the contents probably a naughty.
+		loggingEvent = {
+			startTime: new Date(),
+			categoryName: 'log4js',
+			level: log4js.levels.ERROR,
+			data: [ 'Unable to parse log:', loggingEventString ]
+		};
+	}
+	return loggingEvent;
+} 
+
+/**
+ * Creates an appender. 
+ *
+ * If the current process is a master (`cluster.isMaster`), then this will be a "master appender".
+ * Otherwise this will be a worker appender, that just sends loggingEvents to the master process.
+ *
+ * If you are using this method directly, make sure to provide it with `config.actualAppenders` array 
+ * of actual appender instances.
+ *
+ * Or better use `configure(config, options)`
+ */
+function createAppender(config) {
+
+	if (cluster.isMaster) {
+
+		var masterAppender = function(loggingEvent) {
+	
+			if (config.actualAppenders) {
+				var size = config.actualAppenders.length;
+				for(var i = 0; i < size; i++) {
+					config.actualAppenders[i](loggingEvent);
+				}
+			}
+		}
+		
+		// Listen on new workers
+		cluster.on('fork', function(worker) {
+		
+			worker.on('message', function(message) {
+				if (message.type && message.type === '::log-message') {
+					// console.log("master : " + cluster.isMaster + " received message: " + JSON.stringify(message.event));
+					
+					var loggingEvent = deserializeLoggingEvent(message.event);
+					masterAppender(loggingEvent);
+				}
+			});
+		
+		});
+		
+		return masterAppender;
+		
+	} else {
+
+		return function(loggingEvent) {
+			// If inside the worker process, then send the logger event to master.
+			if (cluster.isWorker) {
+				// console.log("worker " + cluster.worker.id + " is sending message");
+				process.send({ type: '::log-message', event: serializeLoggingEvent(loggingEvent)});
+			}
+		}
+	}
+}
+
+function configure(config, options) {
+
+	if (config.appenders && cluster.isMaster) {
+	
+		var size = config.appenders.length;
+		config.actualAppenders = new Array(size);
+	
+		for(var i = 0; i < size; i++) {
+		
+			log4js.loadAppender(config.appenders[i].type);
+			config.actualAppenders[i] = log4js.appenderMakers[config.appenders[i].type](config.appenders[i], options);
+		
+		}
+	}
+	
+	return createAppender(config);
+}
+
+exports.appender = createAppender;
+exports.configure = configure; 

lib/appenders/gelf.js

@@ -100,7 +100,7 @@ function gelfAppender (layout, host, port, hostname, facility) {
     msg.short_message = msg.full_message;
     
     msg.version="1.0";
-    msg.timestamp = msg.timestamp || new Date().getTime() / 1000 >> 0;
+    msg.timestamp = msg.timestamp || new Date().getTime() / 1000; // log should use millisecond 
     msg.host = hostname;
     msg.level = levelMapping[loggingEvent.level || levels.DEBUG];
     msg.facility = facility;

lib/appenders/multiprocess.js

@@ -94,6 +94,11 @@ function workerAppender(config) {
   }
   
   function write(loggingEvent) {
+	// JSON.stringify(new Error('test')) returns {}, which is not really useful for us.
+	// The following allows us to serialize errors correctly.
+	if (loggingEvent && loggingEvent.stack && JSON.stringify(loggingEvent) === '{}') { // Validate that we really are in this case
+		loggingEvent = {stack : loggingEvent.stack};
+	}
     socket.write(JSON.stringify(loggingEvent), 'utf8');
     socket.write(END_MSG, 'utf8');
   }

lib/date_format.js

@@ -45,7 +45,7 @@ exports.asString = function(/*format,*/ date) {
   var vDay = addZero(date.getDate());
   var vMonth = addZero(date.getMonth()+1);
   var vYearLong = addZero(date.getFullYear());
-  var vYearShort = addZero(date.getFullYear().toString().substring(3,4));
+  var vYearShort = addZero(date.getFullYear().toString().substring(2,4));
   var vYear = (format.indexOf("yyyy") > -1 ? vYearLong : vYearShort);
   var vHour  = addZero(date.getHours());
   var vMinute = addZero(date.getMinutes());

lib/layouts.js

@@ -120,6 +120,7 @@ function messagePassThroughLayout (loggingEvent) {
  *  - %r time in toLocaleTimeString format
  *  - %p log level
  *  - %c log category
+ *  - %h hostname
  *  - %m log data
  *  - %d date in various formats
  *  - %% %
@@ -143,7 +144,7 @@ function messagePassThroughLayout (loggingEvent) {
  */
 function patternLayout (pattern, tokens) {
   var TTCC_CONVERSION_PATTERN  = "%r %p %c - %m%n";
-  var regex = /%(-?[0-9]+)?(\.?[0-9]+)?([\[\]cdmnprx%])(\{([^\}]+)\})?|([^%]+)/;
+  var regex = /%(-?[0-9]+)?(\.?[0-9]+)?([\[\]cdhmnprx%])(\{([^\}]+)\})?|([^%]+)/;
   
   pattern = pattern || TTCC_CONVERSION_PATTERN;
 
@@ -166,6 +167,8 @@ function patternLayout (pattern, tokens) {
       // Pick up special cases
       if (format == "ISO8601") {
         format = dateFormat.ISO8601_FORMAT;
+      } else if (format == "ISO8601_WITH_TZ_OFFSET") {
+        format = dateFormat.ISO8601_WITH_TZ_OFFSET_FORMAT; 
       } else if (format == "ABSOLUTE") {
         format = dateFormat.ABSOLUTETIME_FORMAT;
       } else if (format == "DATE") {
@@ -175,6 +178,10 @@ function patternLayout (pattern, tokens) {
     // Format the date
     return dateFormat.asString(format, loggingEvent.startTime);
   }
+  
+  function hostname() {
+    return os.hostname().toString();
+  }
 
   function formatMessage(loggingEvent) {
     return formatLogData(loggingEvent.data);
@@ -218,6 +225,7 @@ function patternLayout (pattern, tokens) {
   var replacers = {
     'c': categoryName,
     'd': formatAsDate,
+    'h': hostname,
     'm': formatMessage,
     'n': endOfLine,
     'p': logLevel,

package.json

@@ -1,6 +1,6 @@
 {
   "name": "log4js",
-  "version": "0.6.7",
+  "version": "0.6.9",
   "description": "Port of Log4js to work with node.",
   "keywords": [
     "logging",
@@ -29,7 +29,6 @@
   },
   "dependencies": {
     "async": "0.1.15",
-    "dequeue": "1.0.3",
     "semver": "~1.1.4",
     "readable-stream": "~1.0.2"
   },
@@ -38,5 +37,8 @@
     "sandboxed-module": "0.1.3",
     "hook.io": "0.8.10",
     "underscore": "1.2.1"
+  },
+  "browser": {
+    "os": false
   }
 }

test/categoryFilter-test.js

@@ -0,0 +1,83 @@
+'use strict';
+
+var vows = require('vows')
+, fs = require('fs')
+, assert = require('assert');
+
+function remove(filename) {
+  try {
+    fs.unlinkSync(filename);
+  } catch (e) {
+    //doesn't really matter if it failed
+  }
+}
+
+vows.describe('log4js categoryFilter').addBatch({
+  'appender': {
+    topic: function() {
+      
+      var log4js = require('../lib/log4js'), logEvents = [], webLogger, appLogger;
+      log4js.clearAppenders();
+      var appender = require('../lib/appenders/categoryFilter')
+        .appender(
+          ['app'], 
+          function(evt) { logEvents.push(evt); }
+        );
+      log4js.addAppender(appender, ["app","web"]);
+      
+      webLogger = log4js.getLogger("web");
+      appLogger = log4js.getLogger("app");
+      
+      webLogger.debug('This should get logged');
+      appLogger.debug('This should not');
+      webLogger.debug('Hello again');
+      log4js.getLogger('db').debug('This shouldn\'t be included by the appender anyway');
+      
+      return logEvents;
+    },
+    'should only pass matching category' : function(logEvents) {
+      assert.equal(logEvents.length, 2);
+      assert.equal(logEvents[0].data[0], 'This should get logged');
+      assert.equal(logEvents[1].data[0], 'Hello again');
+    }
+  },
+  
+  'configure': {
+    topic: function() {
+      var log4js = require('../lib/log4js')
+      , logger, weblogger;
+      
+      remove(__dirname + '/categoryFilter-web.log');
+      remove(__dirname + '/categoryFilter-noweb.log');
+      
+      log4js.configure('test/with-categoryFilter.json');
+      logger = log4js.getLogger("app");
+      weblogger = log4js.getLogger("web");
+      
+      logger.info('Loading app');
+      logger.debug('Initialising indexes');
+      weblogger.info('00:00:00 GET / 200');
+      weblogger.warn('00:00:00 GET / 500');
+      //wait for the file system to catch up
+      setTimeout(this.callback, 100);
+    },
+    'tmp-tests.log': {
+      topic: function() {
+        fs.readFile(__dirname + '/categoryFilter-noweb.log', 'utf8', this.callback);
+      },
+      'should contain all log messages': function(contents) {
+        var messages = contents.trim().split('\n');
+        assert.deepEqual(messages, ['Loading app','Initialising indexes']);
+      }
+    },
+    'tmp-tests-web.log': {
+      topic: function() {
+        fs.readFile(__dirname + '/categoryFilter-web.log','utf8',this.callback);
+      },
+      'should contain only error and warning log messages': function(contents) {
+        var messages = contents.trim().split('\n');
+        assert.deepEqual(messages, ['00:00:00 GET / 200','00:00:00 GET / 500']);
+      }
+    }
+  }
+}).export(module);

test/clusteredAppender-test.js

@@ -0,0 +1,125 @@
+"use strict";
+var assert = require('assert');
+var vows = require('vows');
+var layouts = require('../lib/layouts');
+var sandbox = require('sandboxed-module');
+var LoggingEvent = require('../lib/logger').LoggingEvent;
+var cluster = require('cluster');
+
+vows.describe('log4js cluster appender').addBatch({
+	'when in master mode': {
+		topic: function() {
+
+			var registeredClusterEvents = [];
+			var loggingEvents = [];
+			
+			// Fake cluster module, so no cluster listeners be really added 
+			var fakeCluster = {
+			
+				on: function(event, callback) {
+					registeredClusterEvents.push(event);
+				},
+				
+				isMaster: true,
+				isWorker: false,
+				
+			};
+		
+			var fakeActualAppender = function(loggingEvent) {
+				loggingEvents.push(loggingEvent);
+			}
+			
+			// Load appender and fake modules in it
+			var appenderModule = sandbox.require('../lib/appenders/clustered', {
+				requires: {
+					'cluster': fakeCluster,
+				}
+			});
+		
+			var masterAppender = appenderModule.appender({
+				actualAppenders: [ fakeActualAppender ]
+			});
+
+			// Actual test - log message using masterAppender
+			masterAppender(new LoggingEvent('wovs', 'Info', ['masterAppender test']));
+			
+			var returnValue = {
+				registeredClusterEvents: registeredClusterEvents,
+				loggingEvents: loggingEvents,
+			};
+		
+			return returnValue;
+		}, 
+		
+		"should register 'fork' event listener on 'cluster'": function(topic) { 
+			assert.equal(topic.registeredClusterEvents[0], 'fork');
+		},
+		
+		"should log using actual appender": function(topic) {
+			assert.equal(topic.loggingEvents[0].data[0], 'masterAppender test');
+		},
+		
+	},
+	
+	'when in worker mode': {
+		
+		topic: function() {
+			
+			var registeredProcessEvents = [];
+			
+			// Fake cluster module, to fake we're inside a worker process
+			var fakeCluster = {
+			
+				isMaster: false,
+				isWorker: true,
+				
+			};
+			
+			var fakeProcess = {
+			
+				send: function(data) {
+					registeredProcessEvents.push(data);
+				},
+				
+			};
+			
+			// Load appender and fake modules in it
+			var appenderModule = sandbox.require('../lib/appenders/clustered', {
+				requires: {
+					'cluster': fakeCluster,
+				},
+				globals: {
+					'process': fakeProcess,
+				}
+			});
+			
+			var workerAppender = appenderModule.appender();
+
+			// Actual test - log message using masterAppender
+			workerAppender(new LoggingEvent('wovs', 'Info', ['workerAppender test']));
+			workerAppender(new LoggingEvent('wovs', 'Info', [new Error('Error test')]));
+			
+			var returnValue = {
+				registeredProcessEvents: registeredProcessEvents,
+			};
+			
+			return returnValue;
+		
+		},
+		
+		"worker appender should call process.send" : function(topic) {
+			assert.equal(topic.registeredProcessEvents[0].type, '::log-message');
+			assert.equal(JSON.parse(topic.registeredProcessEvents[0].event).data[0], "workerAppender test");
+		},
+		
+		"worker should serialize an Error correctly" : function(topic) {
+			assert.equal(topic.registeredProcessEvents[1].type, '::log-message');
+			assert(JSON.parse(topic.registeredProcessEvents[1].event).data[0].stack);
+			var actual = JSON.parse(topic.registeredProcessEvents[1].event).data[0].stack;
+			var expectedRegex = /^Error: Error test/;
+			assert(actual.match(expectedRegex), "Expected: \n\n " + actual + "\n\n to match " + expectedRegex);
+		}
+		
+	}
+
+}).exportTo(module);

test/date_format-test.js

@@ -39,6 +39,13 @@ vows.describe('date_format').addBatch({
         dateFormat.asString(dateFormat.ABSOLUTETIME_FORMAT, date),
         '14:31:30.005'
       );
+    },
+    'should provide a custom format': function(date) {
+      date.getTimezoneOffset = function() { return 120; };
+      assert.equal(
+        dateFormat.asString("O.SSS.ss.mm.hh.dd.MM.yy", date),
+        '-0200.005.30.31.14.11.01.10'
+      );
     }
   }
 }).export(module);

test/fileAppender-test.js

@@ -222,7 +222,7 @@ vows.describe('log4js fileAppender').addBatch({
         , logger;
         //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');
+        log4js.configure('./test/log4js.json');
         logger = log4js.getLogger('tests');
         logger.info('this should not be written to the file');
         logger.warn('this should be written to the file');

test/layouts-test.js

@@ -209,6 +209,9 @@ vows.describe('log4js layouts').addBatch({
     '%n should output a new line': function(args) {
       test(args, '%n', '\n');
     },
+    '%h should output hostname' : function(args) {
+      test(args, '%h', require('os').hostname().toString());
+    },
     '%c should handle category names like java-style package names': function(args) {
       test(args, '%c{1}', 'tests');
       test(args, '%c{2}', 'of.tests');
@@ -221,9 +224,11 @@ vows.describe('log4js layouts').addBatch({
       test(args, '%d', '2010-12-05 14:18:30.045');
     },
     '%d should allow for format specification': function(args) {
+      test(args, '%d{ISO8601_WITH_TZ_OFFSET}', '2010-12-05T14:18:30-0000');
       test(args, '%d{ISO8601}', '2010-12-05 14:18:30.045');
       test(args, '%d{ABSOLUTE}', '14:18:30.045');
       test(args, '%d{DATE}', '05 12 2010 14:18:30.045');
+      test(args, '%d{yy MM dd hh mm ss}', '10 12 05 14 18 30');
       test(args, '%d{yyyy MM dd}', '2010 12 05');
       test(args, '%d{yyyy MM dd hh mm ss SSS}', '2010 12 05 14 18 30 045');
     },

test/multiprocess-test.js

@@ -75,6 +75,7 @@ vows.describe('Multiprocess Appender').addBatch({
       appender('after error, before connect');
       fakeNet.cbs.connect();
       appender('after error, after connect');
+	  appender(new Error('Error test'));
       
       return fakeNet;
     },
@@ -98,6 +99,13 @@ vows.describe('Multiprocess Appender').addBatch({
       assert.equal(net.data[6], JSON.stringify('after error, after connect'));
       assert.equal(net.data[7], '__LOG4JS__');
       assert.equal(net.createConnectionCalled, 2);
+    },
+    'should serialize an Error correctly': function(net) {
+      assert(JSON.parse(net.data[8]).stack, "Expected:\n\n" + net.data[8] + "\n\n to have a 'stack' property");
+      var actual = JSON.parse(net.data[8]).stack;
+      var expectedRegex = /^Error: Error test/;
+      assert(actual.match(expectedRegex), "Expected: \n\n " + actual + "\n\n to match " + expectedRegex);
+
     }
   },
   'worker with timeout': {

test/with-categoryFilter.json

@@ -0,0 +1,23 @@
+{
+  "appenders": [
+    { 
+      "type": "categoryFilter",
+      "exclude": "web",
+      "appender": {
+        "type": "file",
+        "filename": "test/categoryFilter-noweb.log", 
+        "layout": { 
+          "type": "messagePassThrough" 
+        } 
+      }
+    },
+    { 
+      "category": "web", 
+      "type": "file",
+      "filename": "test/categoryFilter-web.log", 
+      "layout": { 
+        "type": "messagePassThrough" 
+      } 
+    }
+  ]
+}