From 648f9c1d3563c97d06d14bd5c9dcea5e409bff59 Mon Sep 17 00:00:00 2001 From: Bryan Clement Date: Mon, 23 Feb 2015 12:08:12 -0800 Subject: [PATCH] logging: refactored child level checking code; added wrapped stringify method that handles thrown exceptions --- LICENSE | 5 ++ lib/util/logger.js | 42 +++++++++-------- package.json | 6 ++- test/unit/licenses.json | 7 ++- test/unit/util/logger.test.js | 86 +++++++++++++++++++++++------------ 5 files changed, 94 insertions(+), 52 deletions(-) diff --git a/LICENSE b/LICENSE index 078410696b..47179472b1 100644 --- a/LICENSE +++ b/LICENSE @@ -301,3 +301,8 @@ json-stringify-safe http://opensource.org/licenses/BSD-2-Clause https-proxy-agent http://opensource.org/licenses/MIT shimmer http://opensource.org/licenses/BSD-2-Clause yakaa http://opensource.org/licenses/MIT +readable-stream http://opensource.org/licenses/MIT +core-util-is http://opensource.org/licenses/MIT +inherits http://opensource.org/licenses/ISC +isarray http://opensource.org/licenses/MIT +string_decoder http://opensource.org/licenses/MIT diff --git a/lib/util/logger.js b/lib/util/logger.js index 8c14ebbf1f..d1918cd2c3 100644 --- a/lib/util/logger.js +++ b/lib/util/logger.js @@ -1,10 +1,18 @@ 'use strict' -var stringify = require('json-stringify-safe') +var stringifySafe = require('json-stringify-safe') var util = require('util') -var Readable = require('stream').Readable +var Readable = require('readable-stream') var os = require('os') +var stringify = function(obj){ + try{ + return stringifySafe(obj) + } catch(err) { + return '[UNPARSABLE OBJECT]' + } +} + module.exports = Logger var LEVELS = { @@ -19,6 +27,7 @@ var LEVELS = { var json_replace = /([^%]|^)((?:%%)*)%j/g util.inherits(Logger, Readable) + function Logger(options, extra) { if(!(this instanceof Logger)) { return new Logger(options, extra) @@ -39,18 +48,9 @@ function Logger(options, extra) { var loggingFunctions = {} Object.keys(LEVELS).forEach(function(_level) { - loggingFunctions[_level] = function checkLevel(extra) { var level = Logger.prototype.coerce(LEVELS[_level]) - if (level < this._level) { - return - } - - if (this.logger && level < this.logger._level) { - return - } - var has_extra = typeof extra === 'object' var args = Array.prototype.slice.call(arguments, has_extra ? 1 : 0) this.write(level, args, has_extra ? extra : null) @@ -73,18 +73,18 @@ Logger.prototype.coerce = function coerce(value) { Logger.prototype.child = function child(extra) { var child = Object.create(loggingFunctions) + child.extra = util._extend({}, this.extra) - child.extra = util._extend(child.extra, extra) + util._extend(child.extra, extra) + var parent = this child.write = function(level, args, extra){ - extra = util._extend(this.extra, extra) - return this.logger.write(level, args, extra) - } - if (this.logger) { - child.logger = this.logger - } else { - child.logger = this + extra = util._extend({}, extra) + var selfExtra = util._extend({}, this.extra) + + extra = util._extend(selfExtra, extra) + return parent.write(level, args, extra) } child.child = Logger.prototype.child @@ -109,6 +109,10 @@ Logger.prototype.write = function write(level, args, extra) { if (!this.enabled) return + if (level < this._level) { + return + } + for(var i = 0, l = args.length; i < l; ++i) { if(typeof args[i] === 'function') { args[i] = args[i].valueOf() diff --git a/package.json b/package.json index 27bcbe7846..7824ca78d9 100644 --- a/package.json +++ b/package.json @@ -74,14 +74,16 @@ "json-stringify-safe": "^5.0.0", "https-proxy-agent": "^0.3.5", "semver": "^4.2.0", - "yakaa": "^1.0.1" + "yakaa": "^1.0.1", + "readable-stream": "^1.1.13" }, "bundledDependencies": [ "continuation-local-storage", "json-stringify-safe", "https-proxy-agent", "semver", - "yakaa" + "yakaa", + "readable-stream" ], "devDependencies": { "JSV": "~4.0.2", diff --git a/test/unit/licenses.json b/test/unit/licenses.json index a567c0249f..cda46c138d 100644 --- a/test/unit/licenses.json +++ b/test/unit/licenses.json @@ -1,14 +1,19 @@ { "async-listener": "BSD-2-Clause", "continuation-local-storage": "BSD", + "core-util-is": "MIT", "emitter-listener": "BSD-2-Clause", "json-stringify-safe": "BSD", "shimmer": "BSD", "yakaa": "MIT", "https-proxy-agent": "MIT", + "inherits": "ISC", + "isarray": "MIT", "agent-base": "MIT", "debug": "MIT*", "extend": "MIT*", "ms": "MIT*", - "semver": "BSD" + "readable-stream": "MIT", + "semver": "BSD", + "string_decoder": "MIT" } diff --git a/test/unit/util/logger.test.js b/test/unit/util/logger.test.js index 7ac24b1e97..66ae1751bf 100644 --- a/test/unit/util/logger.test.js +++ b/test/unit/util/logger.test.js @@ -2,7 +2,6 @@ var Logger = require('../../../lib/util/logger') var chai = require('chai') var expect = chai.expect var through = require('through') -var stream = require('stream') var DEFAULT_KEYS = [ 'hostname', @@ -20,23 +19,22 @@ describe('logger', function() { beforeEach(function() { results = [] - resultStream = through(add_result) logger = Logger({ name: 'my-logger', level: 'info', hostname: 'my-host', - stream: resultStream + stream: through(addResult) }) }) - function add_result(data) { + function addResult(data) { results = results.concat(data.toString().split('\n').filter(Boolean).map(JSON.parse)) } it('should interpolate values', function(done) { logger.info('%d: %s', 1, 'a') logger.info('123', 4, '5') - logger.once('readable', function(){ + process.nextTick(function(){ expect(results.length).equal(2) compare_entry(results[0], '1: a', 30) compare_entry(results[1], '123 4 5', 30) @@ -47,7 +45,7 @@ describe('logger', function() { it('should support prepended extras', function(done) { logger.info({a: 1, b: 2}, '%d: %s', 1, 'a') logger.info({a: 1, b: 2}, '123', 4, '5') - logger.once('readable', function(){ + process.nextTick(function(){ var keys = ['a', 'b'].concat(DEFAULT_KEYS) expect(results.length).equal(2) compare_entry(results[0], '1: a', 30, keys) @@ -67,7 +65,7 @@ describe('logger', function() { logger.warn('warn') logger.error('error') logger.fatal('fatal') - logger.once('readable', function() { + process.nextTick(function() { expect(results.length).equal(4) compare_entry(results[0], 'info', 30) compare_entry(results[1], 'warn', 40) @@ -86,6 +84,7 @@ describe('logger', function() { it('and its children should only log expected levels', function(done) { var child = logger.child({aChild: true}) + var grandchild = child.child({aGrandchild: true}) child.trace('trace') child.debug('debug') @@ -93,19 +92,29 @@ describe('logger', function() { child.warn('warn') child.error('error') child.fatal('fatal') - logger.once('readable', function() { - expect(results.length).equal(4) + grandchild.trace('trace') + grandchild.debug('debug') + grandchild.info('info') + grandchild.warn('warn') + grandchild.error('error') + grandchild.fatal('fatal') + process.nextTick(function() { + expect(results.length).equal(8) compare_entry(results[0], 'info', 30, ['aChild'].concat(DEFAULT_KEYS)) compare_entry(results[1], 'warn', 40, ['aChild'].concat(DEFAULT_KEYS)) compare_entry(results[2], 'error', 50, ['aChild'].concat(DEFAULT_KEYS)) compare_entry(results[3], 'fatal', 60, ['aChild'].concat(DEFAULT_KEYS)) + compare_entry(results[4], 'info', 30, ['aChild', 'aGrandchild'].concat(DEFAULT_KEYS)) + compare_entry(results[5], 'warn', 40, ['aChild', 'aGrandchild'].concat(DEFAULT_KEYS)) + compare_entry(results[6], 'error', 50, ['aChild', 'aGrandchild'].concat(DEFAULT_KEYS)) + compare_entry(results[7], 'fatal', 60, ['aChild', 'aGrandchild'].concat(DEFAULT_KEYS)) logger.level('trace') child.trace('trace') - child.debug('debug') - expect(results.length).equal(6) - compare_entry(results[4], 'trace', 10, ['aChild'].concat(DEFAULT_KEYS)) - compare_entry(results[5], 'debug', 20, ['aChild'].concat(DEFAULT_KEYS)) + grandchild.debug('debug') + expect(results.length).equal(10) + compare_entry(results[8], 'trace', 10, ['aChild'].concat(DEFAULT_KEYS)) + compare_entry(results[9], 'debug', 20, ['aChild', 'aGrandchild'].concat(DEFAULT_KEYS)) done() }) }) @@ -113,7 +122,7 @@ describe('logger', function() { it('should be togglable', function(done) { logger.info('on') logger.enabled = false - logger.on('readable', function(){ + process.nextTick(function(){ expect(results.length).equal(1) logger.info('off') expect(results.length).equal(1) @@ -122,14 +131,14 @@ describe('logger', function() { }) it('should support child loggers', function(done) { - var child_a = logger.child({a: 1}) - var child_b = logger.child({b: 2, c: 3}) - var child_c = child_b.child({c: 6}) - child_a.info('hello a') - child_b.info({b: 5}, 'hello b') - child_c.info({a: 10}, 'hello c') - - logger.on('readable', function(){ + var childA = logger.child({a: 1}) + var childB = logger.child({b: 2, c: 3}) + var childC = childB.child({c: 6}) + childA.info('hello a') + childB.info({b: 5}, 'hello b') + childC.info({a: 10}, 'hello c') + + process.nextTick(function(){ expect(results.length).equal(3) expect(results[0].a).equal(1) compare_entry(results[1], 'hello b', 30, ['b', 'c'].concat(DEFAULT_KEYS)) @@ -148,12 +157,26 @@ describe('logger', function() { var obj = {a: 1, b: 2} obj.self = obj logger.info('JSON: %s', obj) - logger.on('readable', function(){ + process.nextTick(function(){ expect(results.length).equal(1) compare_entry(results[0], 'JSON: {"a":1,"b":2,"self":"[Circular ~]"}', 30) done() }) }) + + it('fail gracefully on unstringifiable objects', function(done){ + var badObj = { + get testData () { + throw new Exception() + } + } + logger.info('JSON: %s', badObj) + process.nextTick(function(){ + expect(results.length).equal(1) + compare_entry(results[0], 'JSON: [UNPARSABLE OBJECT]', 30) + done() + }) + }) }) describe('logger write queue', function() { @@ -170,12 +193,15 @@ describe('logger write queue', function() { logger.once('readable', function() { logger.push = function(str){ - var parts = str.split('\n').filter(Boolean).map(function(a){return a.toString()}).map(JSON.parse) - compare_entry(parts[0], 'b', 30) - compare_entry(parts[1], 'c', 30) - compare_entry(parts[2], 'd', 30) - - return Logger.prototype.push.call(this, str) + var pushed = Logger.prototype.push.call(this, str) + if(pushed){ + var parts = str.split('\n').filter(Boolean).map(function(a){return a.toString()}).map(JSON.parse) + compare_entry(parts[0], 'b', 30) + compare_entry(parts[1], 'c', 30) + compare_entry(parts[2], 'd', 30) + } + + return pushed } logger.info('b') @@ -184,7 +210,7 @@ describe('logger write queue', function() { logger.read() - logger.once('readable', function(){ + process.nextTick(function(){ done() })