all tests pass, now with proper console.log formatting

example-connect-logger.js

@@ -1,9 +1,7 @@
-var log4js = require('./lib/log4js')();
+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();

example.js

@@ -1,13 +1,22 @@
-var log4js = require('./lib/log4js')();
+var log4js = require('./lib/log4js');
-log4js.addAppender(log4js.consoleAppender());
+//log the cheese logger messages to a file, and the console ones as well.
-log4js.addAppender(log4js.fileAppender('cheese.log'), 'cheese');
+log4js.addAppender(log4js.fileAppender('cheese.log'), 'cheese', 'console');
 
 var logger = log4js.getLogger('cheese');
+//only errors and above get logged.
 logger.setLevel('ERROR');
 
+//console logging methds have been replaced with log4js ones.
+console.error("AAArgh! Something went wrong", { some: "otherObject", useful_for: "debug purposes" });
+
+//these will not appear (logging level beneath error)
 logger.trace('Entering cheese testing');
 logger.debug('Got cheese.');
 logger.info('Cheese is Gouda.');
 logger.warn('Cheese is quite smelly.');
-logger.error('Cheese is too ripe!');
+//these end up on the console and in cheese.log
+logger.error('Cheese %s is too ripe!', "gouda");
 logger.fatal('Cheese was breeding ground for listeria.');
+
+
+

lib/layouts.js

@@ -1,4 +1,6 @@
 var dateFormat = require('./date_format')
+, util = require('util')
+, replacementRegExp = /%[sdj]/g
 , layoutMakers = {
     "messagePassThrough": function() { return messagePassThroughLayout; },
     "basic": function() { return basicLayout; },
@@ -10,31 +12,34 @@ var dateFormat = require('./date_format')
     }
 };
 
-/**
+function formatLogData(logData) {
- * BasicLayout is a simple layout for storing the logs. The logs are stored
+    var output = ""
- * in following format:
+    , data = Array.isArray(logData) ? logData.slice() : Array.prototype.slice.call(arguments)
- * <pre>
+    , format = data.shift();
- * [startTime] [logLevel] categoryName - message\n
- * </pre>
- *
- * @author Stephan Strittmatter
- */
-function basicLayout (loggingEvent) {
-    var timestampLevelAndCategory = '[' + dateFormat.asString(loggingEvent.startTime) + '] ';
-    timestampLevelAndCategory += '[' + loggingEvent.level.toString() + '] ';
-    timestampLevelAndCategory += loggingEvent.categoryName + ' - ';
 
-    var output = timestampLevelAndCategory + loggingEvent.message;
+    if (typeof format  === "string") {
+        output = format.replace(replacementRegExp, function(match) {
+            switch (match) {
+            case "%s": return new String(data.shift());
+            case "%d": return new Number(data.shift());
+            case "%j": return JSON.stringify(data.shift());
+            default:
+                return match;
+            };
+        });
+        if (data.length > 0) {
+            output += '\n';
+        }
+    }
 
-    if (loggingEvent.exception) {
+    data.forEach(function (item) {
-	output += '\n'
+        if (item.stack) {
-	output += timestampLevelAndCategory;
+            output += item.stack;
-	if (loggingEvent.exception.stack) {
-	    output += loggingEvent.exception.stack;
         } else {
-	    output += loggingEvent.exception.name + ': '+loggingEvent.exception.message;
+            output += util.inspect(item);
-	}
         }
+    });
+
     return output;
 }
 
@@ -60,8 +65,34 @@ function colorize (str, style) {
         'red'       : [31, 39],
         'yellow'    : [33, 39]
     };
-    return '\033[' + styles[style][0] + 'm' + str +
+    return style ? '\033[' + styles[style][0] + 'm' + str +
-        '\033[' + styles[style][1] + 'm';
+        '\033[' + styles[style][1] + 'm' : str;
+}
+
+function timestampLevelAndCategory(loggingEvent, colour) {
+    var output = colorize(
+        formatLogData(
+            '[%s] [%s] %s - '
+          , dateFormat.asString(loggingEvent.startTime)
+          , loggingEvent.level
+          , loggingEvent.categoryName
+        )
+      , colour
+    );
+    return output;
+}
+
+/**
+ * BasicLayout is a simple layout for storing the logs. The logs are stored
+ * in following format:
+ * <pre>
+ * [startTime] [logLevel] categoryName - message\n
+ * </pre>
+ *
+ * @author Stephan Strittmatter
+ */
+function basicLayout (loggingEvent) {
+    return timestampLevelAndCategory(loggingEvent) + formatLogData(loggingEvent.data);
 }
 
 /**
@@ -69,28 +100,11 @@ function colorize (str, style) {
  * same as basicLayout, but with colours.
  */
 function colouredLayout (loggingEvent) {
-    var timestampLevelAndCategory = colorize('[' + dateFormat.asString(loggingEvent.startTime) + '] ', 'grey');
+    return timestampLevelAndCategory(loggingEvent, loggingEvent.level.colour) + formatLogData(loggingEvent.data);
-    timestampLevelAndCategory += colorize(
-        '[' + loggingEvent.level.toString() + '] ', loggingEvent.level.colour
-    );
-    timestampLevelAndCategory += colorize(loggingEvent.categoryName + ' - ', 'grey');
-
-    var output = timestampLevelAndCategory + loggingEvent.message;
-
-    if (loggingEvent.exception) {
-        output += '\n'
-        output += timestampLevelAndCategory;
-        if (loggingEvent.exception.stack) {
-            output += loggingEvent.exception.stack;
-        } else {
-            output += loggingEvent.exception.name + ': '+loggingEvent.exception.message;
-        }
-    }
-    return output;
 }
 
 function messagePassThroughLayout (loggingEvent) {
-    return loggingEvent.message;
+    return formatLogData(loggingEvent.data);
 }
 
 /**

lib/log4js.js

@@ -181,21 +181,16 @@ function configureLevels(levels) {
  * @constructor
  * @param {String} categoryName name of category
  * @param {Log4js.Level} level level of message
- * @param {String} message message to log
+ * @param {Array} data objects to log
  * @param {Log4js.Logger} logger the associated logger
  * @author Seth Chisamore
  */
-function LoggingEvent (categoryName, level, message, exception, logger) {
+function LoggingEvent (categoryName, level, data, logger) {
     this.startTime = new Date();
     this.categoryName = categoryName;
-    this.message = message;
+    this.data = data;
     this.level = level;
     this.logger = logger;
-    if (exception && exception.message && exception.name) {
-        this.exception = exception;
-    } else if (exception) {
-        this.exception = new Error(sys.inspect(exception));
-    }
 }
 
 /**
@@ -222,8 +217,9 @@ Logger.prototype.removeLevel = function() {
     delete this.level;
 };
 
-Logger.prototype.log = function(logLevel, message, exception) {
+Logger.prototype.log = function(logLevel, args) {
-    var loggingEvent = new LoggingEvent(this.category, logLevel, message, exception, this);
+    var data = Array.prototype.slice.call(args)
+  , loggingEvent = new LoggingEvent(this.category, logLevel, data, this);
     this.emit("log", loggingEvent);
 };
 
@@ -238,9 +234,9 @@ Logger.prototype.isLevelEnabled = function(otherLevel) {
 	    return this.isLevelEnabled(level);
 	};
 
-	Logger.prototype[levelString.toLowerCase()] = function (message, exception) {
+	Logger.prototype[levelString.toLowerCase()] = function () {
 	    if (this.isLevelEnabled(level)) {
-		this.log(level, message, exception);
+		this.log(level, arguments);
 	    }
 	};
     }

test/layouts.js

@@ -9,7 +9,7 @@ vows.describe('log4js layouts').addBatch({
 
         'should apply level colour codes to output': function(layout) {
             var output = layout({
-                message: "nonsense",
+                data: ["nonsense"],
                 startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
                 categoryName: "cheese",
                 level: {
@@ -17,7 +17,20 @@ vows.describe('log4js layouts').addBatch({
                     toString: function() { return "ERROR"; }
                 }
             });
-            assert.equal(output, '\033[90m[2010-12-05 14:18:30.045] \033[39m\033[32m[ERROR] \033[39m\033[90mcheese - \033[39mnonsense');
+            assert.equal(output, '\033[32m[2010-12-05 14:18:30.045] [ERROR] cheese - \033[39mnonsense');
+        },
+
+        'should support the console.log format for the message': function(layout) {
+            var output = layout({
+                data: ["thing %d", 2],
+                startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
+                categoryName: "cheese",
+                level: {
+                    colour: "green",
+                    toString: function() { return "ERROR"; }
+                }
+            });
+            assert.equal(output, '\033[32m[2010-12-05 14:18:30.045] [ERROR] cheese - \033[39mthing 2');
         }
     },
 
@@ -27,7 +40,7 @@ vows.describe('log4js layouts').addBatch({
         },
         'should take a logevent and output only the message' : function(layout) {
             assert.equal(layout({
-                message: "nonsense",
+                data: ["nonsense"],
                 startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
                 categoryName: "cheese",
                 level: {
@@ -35,6 +48,17 @@ vows.describe('log4js layouts').addBatch({
                     toString: function() { return "ERROR"; }
                 }
             }), "nonsense");
+        },
+        'should support the console.log format for the message' : function(layout) {
+              assert.equal(layout({
+                  data: ["thing %d", 1]
+                , startTime: new Date(2010, 11, 5, 14, 18, 30, 45)
+                , categoryName: "cheese"
+                , level : {
+                    colour: "green"
+                  , toString: function() { return "ERROR"; }
+                }
+              }), "thing 1");
           }
     },
 
@@ -42,7 +66,7 @@ vows.describe('log4js layouts').addBatch({
         topic: function() {
             var layout = require('../lib/layouts').basicLayout,
             event = {
-                message: 'this is a test',
+                data: ['this is a test'],
                 startTime: new Date(2010, 11, 5, 14, 18, 30, 45),
                 categoryName: "tests",
                 level: {
@@ -61,29 +85,29 @@ vows.describe('log4js layouts').addBatch({
             error = new Error("Some made-up error"),
             stack = error.stack.split(/\n/);
 
-            event.exception = error;
+            event.data = ['this is a test', error];
             output = layout(event);
             lines = output.split(/\n/);
 
             assert.length(lines, stack.length+1);
             assert.equal(lines[0], "[2010-12-05 14:18:30.045] [DEBUG] tests - this is a test");
-            assert.equal(lines[1], "[2010-12-05 14:18:30.045] [DEBUG] tests - Error: Some made-up error");
+            assert.equal(lines[1], "Error: Some made-up error");
             for (var i = 1; i < stack.length; i++) {
                 assert.equal(lines[i+1], stack[i]);
             }
         },
-        'should output a name and message if the event has something that pretends to be an error': function(args) {
+        'should output any extra data in the log event as util.inspect strings': function(args) {
             var layout = args[0], event = args[1], output, lines;
-            event.exception = {
+            event.data = ['this is a test', {
                     name: 'Cheese',
                     message: 'Gorgonzola smells.'
-            };
+            }];
             output = layout(event);
             lines = output.split(/\n/);
 
             assert.length(lines, 2);
             assert.equal(lines[0], "[2010-12-05 14:18:30.045] [DEBUG] tests - this is a test");
-            assert.equal(lines[1], "[2010-12-05 14:18:30.045] [DEBUG] tests - Cheese: Gorgonzola smells.");
+            assert.equal(lines[1], "{ name: 'Cheese', message: 'Gorgonzola smells.' }");
         }
     }
 }).export(module);

test/logging.js

@@ -37,7 +37,7 @@ vows.describe('log4js').addBatch({
 
 	    'should emit log events': function(events) {
 		assert.equal(events[0].level.toString(), 'DEBUG');
-		assert.equal(events[0].message, 'Debug event');
+		assert.equal(events[0].data[0], 'Debug event');
 		assert.instanceOf(events[0].startTime, Date);
 	    },
 
@@ -47,14 +47,9 @@ vows.describe('log4js').addBatch({
 	    },
 
             'should include the error if passed in': function (events) {
-                assert.instanceOf(events[2].exception, Error);
+                assert.instanceOf(events[2].data[1], Error);
-                assert.equal(events[2].exception.message, 'Pants are on fire!');
+                assert.equal(events[2].data[1].message, 'Pants are on fire!');
-            },
+            }
-
-            'should convert things that claim to be errors into Error objects': function (events) {
-                assert.instanceOf(events[3].exception, Error);
-                assert.equal(events[3].exception.message, "{ err: 127, cause: 'incendiary underwear' }");
-            },
 
 	},
 
@@ -321,7 +316,7 @@ vows.describe('log4js').addBatch({
                 var appenderEvent, appender = function(evt) { appenderEvent = evt; }, logger = log4js.getLogger("tests");
                 log4js.addAppender(appender);
                 logger.debug("This is a test");
-                assert.equal(appenderEvent.message, "This is a test");
+                assert.equal(appenderEvent.data[0], "This is a test");
                 assert.equal(appenderEvent.categoryName, "tests");
                 assert.equal(appenderEvent.level.toString(), "DEBUG");
             },
@@ -333,14 +328,14 @@ vows.describe('log4js').addBatch({
                 cheeseLogger = log4js.getLogger('cheese');
                 cheeseLogger.debug('This is a test');
                 assert.deepEqual(appenderEvent, otherEvent);
-                assert.equal(otherEvent.message, 'This is a test');
+                assert.equal(otherEvent.data[0], 'This is a test');
                 assert.equal(otherEvent.categoryName, 'cheese');
 
                 otherEvent = undefined;
                 appenderEvent = undefined;
                 log4js.getLogger('pants').debug("this should not be propagated to otherEvent");
                 assert.isUndefined(otherEvent);
-                assert.equal(appenderEvent.message, "this should not be propagated to otherEvent");
+                assert.equal(appenderEvent.data[0], "this should not be propagated to otherEvent");
             }
         },
 
@@ -349,7 +344,7 @@ vows.describe('log4js').addBatch({
                 var appenderEvent, appender = function(evt) { appenderEvent = evt; }, logger = log4js.getLogger("tests");
                 log4js.addAppender(appender, 'tests');
                 logger.debug('this is a category test');
-                assert.equal(appenderEvent.message, 'this is a category test');
+                assert.equal(appenderEvent.data[0], 'this is a category test');
 
                 appenderEvent = undefined;
                 log4js.getLogger('some other category').debug('Cheese');
@@ -363,12 +358,12 @@ vows.describe('log4js').addBatch({
                 log4js.addAppender(appender, 'tests', 'biscuits');
 
                 logger.debug('this is a test');
-                assert.equal(appenderEvent.message, 'this is a test');
+                assert.equal(appenderEvent.data[0], 'this is a test');
                 appenderEvent = undefined;
 
                 var otherLogger = log4js.getLogger('biscuits');
                 otherLogger.debug("mmm... garibaldis");
-                assert.equal(appenderEvent.message, "mmm... garibaldis");
+                assert.equal(appenderEvent.data[0], "mmm... garibaldis");
 
                 appenderEvent = undefined;
 
@@ -380,12 +375,12 @@ vows.describe('log4js').addBatch({
                 log4js.addAppender(appender, ['tests', 'pants']);
 
                 log4js.getLogger('tests').debug('this is a test');
-                assert.equal(appenderEvent.message, 'this is a test');
+                assert.equal(appenderEvent.data[0], 'this is a test');
 
                 appenderEvent = undefined;
 
                 log4js.getLogger('pants').debug("big pants");
-                assert.equal(appenderEvent.message, "big pants");
+                assert.equal(appenderEvent.data[0], "big pants");
 
                 appenderEvent = undefined;
 
@@ -472,8 +467,8 @@ vows.describe('log4js').addBatch({
         },
         'should only pass log events greater than or equal to its own level' : function(logEvents) {
             assert.length(logEvents, 2);
-            assert.equal(logEvents[0].message, 'this should, though');
+            assert.equal(logEvents[0].data[0], 'this should, though');
-            assert.equal(logEvents[1].message, 'so should this');
+            assert.equal(logEvents[1].data[0], 'so should this');
         }
     },
 
@@ -509,18 +504,23 @@ vows.describe('log4js').addBatch({
             fakeConsole.info("some info");
             fakeConsole.warn("a warning");
 
+            fakeConsole.log("cheese (%s) and biscuits (%s)", "gouda", "garibaldis");
+            fakeConsole.log({ lumpy: "tapioca" });
+            fakeConsole.log("count %d", 123);
+            fakeConsole.log("stringify %j", { lumpy: "tapioca" });
+
             return logEvents;
         },
         'should replace console.log methods with log4js ones': function(logEvents) {
-            assert.equal(logEvents[0].message, "Some debug message someone put in a module");
+            assert.equal(logEvents[0].data[0], "Some debug message someone put in a module");
             assert.equal(logEvents[0].level.toString(), "INFO");
-            assert.equal(logEvents[1].message, "Some debug");
+            assert.equal(logEvents[1].data[0], "Some debug");
             assert.equal(logEvents[1].level.toString(), "DEBUG");
-            assert.equal(logEvents[2].message, "An error");
+            assert.equal(logEvents[2].data[0], "An error");
             assert.equal(logEvents[2].level.toString(), "ERROR");
-            assert.equal(logEvents[3].message, "some info");
+            assert.equal(logEvents[3].data[0], "some info");
             assert.equal(logEvents[3].level.toString(), "INFO");
-            assert.equal(logEvents[4].message, "a warning");
+            assert.equal(logEvents[4].data[0], "a warning");
             assert.equal(logEvents[4].level.toString(), "WARN");
         }
     },
@@ -533,7 +533,7 @@ vows.describe('log4js').addBatch({
 	    secondLog4js = require('../lib/log4js');
 	    secondLog4js.getLogger().info("This should go to the appender defined in firstLog4js");
 
-	    assert.equal(logEvent.message, "This should go to the appender defined in firstLog4js");
+	    assert.equal(logEvent.data[0], "This should go to the appender defined in firstLog4js");
 	}
     }