From 5868856a7d6bdd2197360f8e72d995839e42c805 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Wed, 13 Jul 2011 18:12:29 +1000 Subject: [PATCH] all tests pass, now with proper console.log formatting --- example-connect-logger.js | 6 +-- example.js | 21 +++++--- lib/layouts.js | 102 ++++++++++++++++++++++---------------- lib/log4js.js | 20 +++----- test/layouts.js | 46 +++++++++++++---- test/logging.js | 50 +++++++++---------- 6 files changed, 143 insertions(+), 102 deletions(-) diff --git a/example-connect-logger.js b/example-connect-logger.js index 55b0572..705ef53 100644 --- a/example-connect-logger.js +++ b/example-connect-logger.js @@ -1,9 +1,7 @@ -var log4js = require('./lib/log4js')(); -log4js.addAppender(log4js.consoleAppender()); +var log4js = require('./lib/log4js'); log4js.addAppender(log4js.fileAppender('cheese.log'), 'cheese'); - -var logger = log4js.getLogger('cheese'); +var logger = log4js.getLogger('cheese'); logger.setLevel('INFO'); var app = require('express').createServer(); diff --git a/example.js b/example.js index 66d9ce4..ddcaf05 100644 --- a/example.js +++ b/example.js @@ -1,13 +1,22 @@ -var log4js = require('./lib/log4js')(); -log4js.addAppender(log4js.consoleAppender()); -log4js.addAppender(log4js.fileAppender('cheese.log'), 'cheese'); - +var log4js = require('./lib/log4js'); +//log the cheese logger messages to a file, and the console ones as well. +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.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.'); + + + diff --git a/lib/layouts.js b/lib/layouts.js index c535556..67fb772 100644 --- a/lib/layouts.js +++ b/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') } }; -/** - * BasicLayout is a simple layout for storing the logs. The logs are stored - * in following format: - * 
- * [startTime] [logLevel] categoryName - message\n
- *
- * - * @author Stephan Strittmatter - */ -function basicLayout (loggingEvent) { - var timestampLevelAndCategory = '[' + dateFormat.asString(loggingEvent.startTime) + '] '; - timestampLevelAndCategory += '[' + loggingEvent.level.toString() + '] '; - timestampLevelAndCategory += loggingEvent.categoryName + ' - '; +function formatLogData(logData) { + var output = "" + , data = Array.isArray(logData) ? logData.slice() : Array.prototype.slice.call(arguments) + , format = data.shift(); - 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; - } + 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'; + } } + + data.forEach(function (item) { + if (item.stack) { + output += item.stack; + } else { + 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 + - '\033[' + styles[style][1] + 'm'; + return style ? '\033[' + styles[style][0] + 'm' + str + + '\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: + * 
+ * [startTime] [logLevel] categoryName - message\n
+ *
+ * + * @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'); - 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; + return timestampLevelAndCategory(loggingEvent, loggingEvent.level.colour) + formatLogData(loggingEvent.data); } function messagePassThroughLayout (loggingEvent) { - return loggingEvent.message; + return formatLogData(loggingEvent.data); } /** diff --git a/lib/log4js.js b/lib/log4js.js index e42c809..7b40b29 100644 --- a/lib/log4js.js +++ b/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) { - var loggingEvent = new LoggingEvent(this.category, logLevel, message, exception, this); +Logger.prototype.log = function(logLevel, args) { + 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); } }; } diff --git a/test/layouts.js b/test/layouts.js index 719c611..198cae8 100644 --- a/test/layouts.js +++ b/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,14 +48,25 @@ 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"); + } }, 'basicLayout': { 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); diff --git a/test/logging.js b/test/logging.js index 8984bb4..fa1aa43 100644 --- a/test/logging.js +++ b/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.equal(events[2].exception.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' }"); - }, + assert.instanceOf(events[2].data[1], Error); + assert.equal(events[2].data[1].message, 'Pants are on fire!'); + } }, @@ -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[1].message, 'so should this'); + assert.equal(logEvents[0].data[0], 'this should, though'); + 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"); } }