From 6be712727bbc93e3811b0aa37110e380991657ea Mon Sep 17 00:00:00 2001 From: Andrew Houghton Date: Wed, 7 Dec 2016 09:55:02 -0500 Subject: [PATCH] This is a -- possibly stopgap -- solution to the need for levels beyond the default set. It's imperfect in re: dtrace support, but it's also self-contained and easy to understand. Caveats: - There's no way to dynamically add dtrace probes after-the-fact of logger creation, so there's no way to trace levels in loggers that were instantiated prior to the level creation - I think this is completely safe in-re: Logger fields; we may be adding functions to the prototype left-and-right, but they'll be shadowed by the actual Logger instance, and we won't overwrite anything that exists - I'm a little uncomfortable with all the hand-holding / don't-shoot-yourself-in-the-foot going on in the createLogger call, but it's certainly safer - The documentation could be better --- README.md | 29 ++++++- bin/bunyan | 104 ++++++++++++++++++++---- lib/bunyan.js | 112 +++++++++++++++++++------- test/cli.test.js | 96 ++++++++++++++++++++++ test/corpus/mapped-levels.log | 9 +++ test/create-level.test.js | 147 ++++++++++++++++++++++++++++++++++ 6 files changed, 452 insertions(+), 45 deletions(-) create mode 100644 test/corpus/mapped-levels.log create mode 100644 test/create-level.test.js diff --git a/README.md b/README.md index 1e225ecb..e5b44129 100644 --- a/README.md +++ b/README.md @@ -494,7 +494,6 @@ log.levels(0, "info") // can use "info" et al aliases log.levels("foo", WARN) // set stream named "foo" to WARN ``` - ## Level suggestions Trent's biased suggestions for server apps: Use "debug" sparingly. Information @@ -508,6 +507,34 @@ ever log at `trace`-level. Fine control over log output should be up to the app using a library. Having a library that spews log output at higher levels gets in the way of a clear story in the *app* logs. +## Creating new Levels + +You can register a new level: + + ```js + var bunyan = require('bunyan'); + + bunyan.createLevel('notice', 35); + ``` + + .. at which point that level is usable in (most of) the normal ways: + + + ```js + log.level("notice") // set all streams to level NOTICE + log.notice("this will be logged"); + + log.level("warn") // set all streams to level WARN + log.notice("this will not be logged"); + ``` + + There are some caveats: + + 1. If you require DTrace support (see below), you need to create + new levels prior to instantiating Loggers; levels will work if + you do it the other way around, but DTrace won't be fired. + 2. No constants are defined for dynamically created levels; you'll + need to track your level values yourself. # Log Record Fields diff --git a/bin/bunyan b/bin/bunyan index a1c38512..eac30010 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -59,7 +59,7 @@ var OM_FROM_NAME = { }; -// Levels +// Default Levels var TRACE = 10; var DEBUG = 20; var INFO = 30; @@ -75,15 +75,71 @@ var levelFromName = { 'error': ERROR, 'fatal': FATAL }; + +function colorFromLevel(level) { + if (level <= 10) { + return 'white'; + } + + if (level <= 20) { + return 'yellow'; + } + + if (level <= 30) { + return 'cyan'; + } + + if (level <= 40) { + return 'magenta'; + } + + if (level <= 50) { + return 'red'; + } + + return 'inverse'; +} + +var maxNameLength = 0; var nameFromLevel = {}; var upperNameFromLevel = {}; var upperPaddedNameFromLevel = {}; -Object.keys(levelFromName).forEach(function (name) { - var lvl = levelFromName[name]; +var LEVELS = {}; + +function mkLevel(name, lvl) { nameFromLevel[lvl] = name; upperNameFromLevel[lvl] = name.toUpperCase(); - upperPaddedNameFromLevel[lvl] = ( - name.length === 4 ? ' ' : '') + name.toUpperCase(); + + if (name.length > maxNameLength) { + // pad, pad. + Object.keys(upperPaddedNameFromLevel).forEach(function(l) { + var paddedName = upperPaddedNameFromLevel[l]; + for (var delta = name.length - maxNameLength; delta > 0; delta--) { + paddedName = ' ' + paddedName; + } + upperPaddedNameFromLevel[l] = paddedName; + }); + maxNameLength = name.length; + } + + if (name.length < maxNameLength) { + for (var delta = maxNameLength - name.length; delta > 0; delta--) { + name = ' ' + name; + } + } + upperPaddedNameFromLevel[lvl] = name.toUpperCase(); + + LEVELS[name.toUpperCase()] = lvl; + + // if adding mappings.. + if (!levelFromName[name]) { + levelFromName[name] = lvl; + } +} + +Object.keys(levelFromName).forEach(function (name) { + var lvl = levelFromName[name]; + mkLevel(name, lvl); }); @@ -249,6 +305,13 @@ function printHelp() { p(' -0 shortcut for `-o bunyan`'); p(' -L, --time local'); p(' Display time field in local time, rather than UTC.'); + p(' --map "NUM=NAME"'); + p(' Map specific error levels to names in the output. You'); + p(' can pass this option multiple times, first use wins, e.g.'); + p(' --map "35=notice" --map "35=security"'); + p(' will map level 35 to the string \'NOTICE\'. You cannot'); + p(' override the default mappings (i.e., 30 will always mean'); + p(' INFO).'); p(''); p('Environment Variables:'); p(' BUNYAN_NO_COLOR Set to a non-empty value to force no output '); @@ -505,6 +568,25 @@ function parseArgv(argv) { if (parsed.outputMode === undefined) { throw new Error('unknown output mode: "'+name+'"'); } + break; + case '--map': + var lvlArg = args.shift().trim(); + var lvlIdx = lvlArg.indexOf('='); + var lvl = null; + var mapsTo = null; + if (lvlIdx !== -1) { + lvl = lvlArg.substring(0, lvlIdx).trim(); + mapsTo = lvlArg.substring(lvlIdx+1).trim(); + } + + if (parseInt(lvl, 10).toString() !== lvl || !mapsTo) { + throw new Error('level argument must be NUMBER=NAME, e.g. "35=notice"'); + } + + if (!nameFromLevel[lvl]) { + mkLevel(mapsTo, lvl); + } + break; case '-j': // output with JSON.stringify parsed.outputMode = OM_JSON; @@ -699,7 +781,7 @@ function isValidRecord(rec) { } var minValidRecord = { v: 0, //TODO: get this from bunyan.LOG_VERSION - level: INFO, + level: LEVELS.INFO, name: 'name', hostname: 'hostname', pid: 123, @@ -815,15 +897,7 @@ function emitRecord(rec, line, opts, stylize) { var level = (upperPaddedNameFromLevel[rec.level] || 'LVL' + rec.level); if (opts.color) { - var colorFromLevel = { - 10: 'white', // TRACE - 20: 'yellow', // DEBUG - 30: 'cyan', // INFO - 40: 'magenta', // WARN - 50: 'red', // ERROR - 60: 'inverse', // FATAL - }; - level = stylize(level, colorFromLevel[rec.level]); + level = stylize(level, colorFromLevel(rec.level)); } delete rec.level; diff --git a/lib/bunyan.js b/lib/bunyan.js index 778c919b..0370b4e5 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -239,11 +239,11 @@ var _warned = {}; function ConsoleRawStream() {} ConsoleRawStream.prototype.write = function (rec) { - if (rec.level < INFO) { + if (rec.level < defaultLevels.INFO) { console.log(rec); - } else if (rec.level < WARN) { + } else if (rec.level < defaultLevels.WARN) { console.info(rec); - } else if (rec.level < ERROR) { + } else if (rec.level < defaultLevels.ERROR) { console.warn(rec); } else { console.error(rec); @@ -253,20 +253,22 @@ ConsoleRawStream.prototype.write = function (rec) { //---- Levels -var TRACE = 10; -var DEBUG = 20; -var INFO = 30; -var WARN = 40; -var ERROR = 50; -var FATAL = 60; +var defaultLevels = { + TRACE: 10, + DEBUG: 20, + INFO: 30, + WARN: 40, + ERROR: 50, + FATAL: 60 +}; var levelFromName = { - 'trace': TRACE, - 'debug': DEBUG, - 'info': INFO, - 'warn': WARN, - 'error': ERROR, - 'fatal': FATAL + 'trace': defaultLevels.TRACE, + 'debug': defaultLevels.DEBUG, + 'info': defaultLevels.INFO, + 'warn': defaultLevels.WARN, + 'error': defaultLevels.ERROR, + 'fatal': defaultLevels.FATAL }; var nameFromLevel = {}; Object.keys(levelFromName).forEach(function (name) { @@ -313,6 +315,57 @@ function isWritable(obj) { } +/** + * Create a new logging level, and expose it. Name must be case-insensitive + * unique, and is normalized to lowercase. Level must not exist, and is + * normalized to the floor of its absolute value (e.g., -2.3 becomes 2, -32 + * becomes 32). + * + * If you need DTrace support, create new levels *prior* to creating any + * loggers (levels created after Loggers will work, they just won't trigger + * DTrace). + * + * @api public + */ + +function createLevel(name, level) { + if (typeof name !== 'string' || !name.trim()) { + throw new TypeError('name (string) is required'); + } + + name = name.toLowerCase(); + + if (!name.match(/^[a-z_]+$/)) { + throw new Error('level \'' + name + '\' is invalid'); + } + + if (levelFromName[name]) { + throw new Error('level \'' + name + '\' already exists'); + } + + if (Logger.prototype[name]) { + throw new Error('level \'' + name + '\' is invalid'); + } + + if (typeof level !== 'number') { + throw new TypeError('level (number) is required') + } + + level = Math.floor(Math.abs(level)); + + if (nameFromLevel[level]) { + throw new Error('level \'' + name + '\' would duplicate \'' + nameFromLevel[level] + '\''); + } + + levelFromName[name] = level; + nameFromLevel[level] = name; + + Logger.prototype[name] = mkLogEmitter(level); + + return Logger.prototype[name]; +} + + //---- Logger class /** @@ -551,7 +604,7 @@ util.inherits(Logger, EventEmitter); Logger.prototype.addStream = function addStream(s, defaultLevel) { var self = this; if (defaultLevel === null || defaultLevel === undefined) { - defaultLevel = INFO; + defaultLevel = defaultLevels.INFO; } s = objCopy(s); @@ -1061,7 +1114,7 @@ function mkLogEmitter(minLevel) { str = this._emit(rec); } - if (probes) { + if (probes && probes[minLevel]) { probes[minLevel].fire(mkProbeArgs, str, log, minLevel, msgArgs); } } @@ -1086,12 +1139,12 @@ function mkLogEmitter(minLevel) { * arguments that are handled like * [util.format](http://nodejs.org/docs/latest/api/all.html#util.format). */ -Logger.prototype.trace = mkLogEmitter(TRACE); -Logger.prototype.debug = mkLogEmitter(DEBUG); -Logger.prototype.info = mkLogEmitter(INFO); -Logger.prototype.warn = mkLogEmitter(WARN); -Logger.prototype.error = mkLogEmitter(ERROR); -Logger.prototype.fatal = mkLogEmitter(FATAL); +Logger.prototype.trace = mkLogEmitter(defaultLevels.TRACE); +Logger.prototype.debug = mkLogEmitter(defaultLevels.DEBUG); +Logger.prototype.info = mkLogEmitter(defaultLevels.INFO); +Logger.prototype.warn = mkLogEmitter(defaultLevels.WARN); +Logger.prototype.error = mkLogEmitter(defaultLevels.ERROR); +Logger.prototype.fatal = mkLogEmitter(defaultLevels.FATAL); @@ -1555,15 +1608,16 @@ RingBuffer.prototype.destroySoon = function () { module.exports = Logger; -module.exports.TRACE = TRACE; -module.exports.DEBUG = DEBUG; -module.exports.INFO = INFO; -module.exports.WARN = WARN; -module.exports.ERROR = ERROR; -module.exports.FATAL = FATAL; +module.exports.TRACE = defaultLevels.TRACE; +module.exports.DEBUG = defaultLevels.DEBUG; +module.exports.INFO = defaultLevels.INFO; +module.exports.WARN = defaultLevels.WARN; +module.exports.ERROR = defaultLevels.ERROR; +module.exports.FATAL = defaultLevels.FATAL; module.exports.resolveLevel = resolveLevel; module.exports.levelFromName = levelFromName; module.exports.nameFromLevel = nameFromLevel; +module.exports.createLevel = createLevel; module.exports.VERSION = VERSION; module.exports.LOG_VERSION = LOG_VERSION; diff --git a/test/cli.test.js b/test/cli.test.js index 99ba9b9e..110918d3 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -530,3 +530,99 @@ test('should only show nonempty response bodies', function (t) { t.end(); }); }); + +test('--map ""', function (t) { + exec(BUNYAN + ' --map ""', function (err, stdout, stderr) { + t.ok(err, 'should error out') + t.equal(err.code, 1, '... with exit code 1') + t.end(); + }); +}); + +test('--map "=bogus"', function (t) { + exec(BUNYAN + ' --map "=bogus"', function (err, stdout, stderr) { + t.ok(err, 'should error out') + t.equal(err.code, 1, '... with exit code 1') + t.end(); + }); +}); + +test('--map "10="', function (t) { + exec(BUNYAN + ' --map "10="', function (err, stdout, stderr) { + t.ok(err, 'should error out') + t.equal(err.code, 1, '... with exit code 1') + t.end(); + }); +}); + +test('--map "bogus="', function (t) { + exec(BUNYAN + ' --map "bogus="', function (err, stdout, stderr) { + t.ok(err, 'should error out') + t.equal(err.code, 1, '... with exit code 1') + t.end(); + }); +}); + +test('--map "35=notice"', function (t) { + var expect = [ + '# levels\n', + '[2012-02-08T22:56:50.856Z] TRACE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:51.856Z] DEBUG: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:53.856Z] NOTICE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:54.856Z] WARN: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:55.856Z] ERROR: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:56.856Z] LVL55: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:57.856Z] FATAL: myservice/123 on example.com: My message\n' + ].join(''); + var cmd = _('%s --map "35=notice" %s/corpus/mapped-levels.log', + BUNYAN, __dirname); + exec(cmd, function (err, stdout, stderr) { + t.ifError(err); + t.equal(stdout, expect); + t.done(); + }); +}); + +test('--map "35=notice" --map "55=test"', function (t) { + var expect = [ + '# levels\n', + '[2012-02-08T22:56:50.856Z] TRACE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:51.856Z] DEBUG: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:53.856Z] NOTICE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:54.856Z] WARN: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:55.856Z] ERROR: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:56.856Z] TEST: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:57.856Z] FATAL: myservice/123 on example.com: My message\n' + ].join(''); + var cmd = _('%s --map "35=notice" --map "55=TEST" %s/corpus/mapped-levels.log', + BUNYAN, __dirname); + exec(cmd, function (err, stdout, stderr) { + t.ifError(err); + t.equal(stdout, expect); + t.done(); + }); +}); + +test('--map "35=notice" --map "55=TEST" --map="35=TEST"', function (t) { + var expect = [ + '# levels\n', + '[2012-02-08T22:56:50.856Z] TRACE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:51.856Z] DEBUG: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:53.856Z] NOTICE: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:54.856Z] WARN: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:55.856Z] ERROR: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:56.856Z] TEST: myservice/123 on example.com: My message\n', + '[2012-02-08T22:56:57.856Z] FATAL: myservice/123 on example.com: My message\n' + ].join(''); + var cmd = _('%s --map "35=notice" --map "55=TEST" %s/corpus/mapped-levels.log', + BUNYAN, __dirname); + exec(cmd, function (err, stdout, stderr) { + t.ifError(err); + t.equal(stdout, expect); + t.done(); + }); +}); + diff --git a/test/corpus/mapped-levels.log b/test/corpus/mapped-levels.log new file mode 100644 index 00000000..1c32bd6b --- /dev/null +++ b/test/corpus/mapped-levels.log @@ -0,0 +1,9 @@ +# levels +{"name":"myservice","pid":123,"hostname":"example.com","level":10,"msg":"My message","time":"2012-02-08T22:56:50.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":20,"msg":"My message","time":"2012-02-08T22:56:51.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":30,"msg":"My message","time":"2012-02-08T22:56:52.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":35,"msg":"My message","time":"2012-02-08T22:56:53.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":40,"msg":"My message","time":"2012-02-08T22:56:54.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":50,"msg":"My message","time":"2012-02-08T22:56:55.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":55,"msg":"My message","time":"2012-02-08T22:56:56.856Z","v":0} +{"name":"myservice","pid":123,"hostname":"example.com","level":60,"msg":"My message","time":"2012-02-08T22:56:57.856Z","v":0} diff --git a/test/create-level.test.js b/test/create-level.test.js new file mode 100644 index 00000000..9ada4dcf --- /dev/null +++ b/test/create-level.test.js @@ -0,0 +1,147 @@ +/* + * Copyright (c) 2014 Trent Mick. All rights reserved. + * + * Test the `log.level(...)`. + */ + +var util = require('util'), + format = util.format, + inspect = util.inspect; +var p = console.log; + +var bunyan = require('../lib/bunyan'); + +// node-tap API +if (require.cache[__dirname + '/tap4nodeunit.js']) + delete require.cache[__dirname + '/tap4nodeunit.js']; +var tap4nodeunit = require('./tap4nodeunit.js'); +var after = tap4nodeunit.after; +var before = tap4nodeunit.before; +var test = tap4nodeunit.test; + +// ---- test level creation failures + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel({}, 10); }, + /* JSSTYLED */ + /name \(string\) is required/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel(null, 10); }, + /* JSSTYLED */ + /name \(string\) is required/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel(" ", 10); }, + /* JSSTYLED */ + /name \(string\) is required/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel('info', 10); }, + /* JSSTYLED */ + /level 'info' already exists/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel('iNFo', 10); }, + /* JSSTYLED */ + /level 'info' already exists/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel('child', 10); }, + /* JSSTYLED */ + /level 'child' is invalid/); + + t.end(); +}); + +test('bunyan.createLevel(, ...)', function (t) { + t.throws(function () { bunyan.createLevel('abc34', 10); }, + /* JSSTYLED */ + /level 'abc34' is invalid/); + + t.end(); +}); + +test('bunyan.createLevel(..., )', function (t) { + t.throws(function () { bunyan.createLevel('abc', 10); }, + /* JSSTYLED */ + /level 'abc' would duplicate 'trace'/); + + t.end(); +}); + +test('bunyan.createLevel(..., )', function (t) { + t.throws(function () { bunyan.createLevel('abc', {}); }, + /* JSSTYLED */ + /level \(number\) is required/); + + t.end(); +}); + +test('bunyan.createLevel(, )', function (t) { + bunyan.createLevel('createlevel_test', 1); + t.end(); +}); + + +bunyan.createLevel('notice', 35); + +// ---- test logging occurs as expected around level 35 / notice + +function Catcher() { + this.records = []; +} +Catcher.prototype.write = function (record) { + this.records.push(record); +} +var catcher = new Catcher(); +var log1 = new bunyan.createLogger({ + name: 'log1', + streams: [ + { + type: 'raw', + stream: catcher, + level: 'warn' + } + ] +}); + +test('log.notice() at level info', function(t) { + log1.level('info'); + log1.notice('at level info'); + var rec = catcher.records[catcher.records.length - 1]; + t.equal(rec.msg, 'at level info', 'log.notice msg is "at level info"'); + t.done(); +}); + +test('log.notice() at level 37', function(t) { + log1.level(37); + log1.notice('at level 37'); + var rec = catcher.records[catcher.records.length - 1]; + t.notEqual(rec.msg, 'at level 37', 'log.notice msg is not "at level 37"'); + t.done(); +}); + +test('log.notice() at level warn', function(t) { + log1.level('warn'); + log1.notice('at level warn'); + var rec = catcher.records[catcher.records.length - 1]; + t.notEqual(rec.msg, 'at level warn', 'log.notice msg is not "at level warn"'); + t.done(); +}); +