From 6806112d8ab74e265b48da33ef7f04fc7009c99c Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Sat, 4 Feb 2012 00:08:37 -0800 Subject: [PATCH] - `log.clone` -> `log.child` to better reflect the relationship: streams and serializers are inherited. Streams can't be removed as part of the child creation. The child doesn't own the parent's streams (so can't close them). - Clean up Logger creation. The goal here was to ensure `log.child` usage is fast. TODO: measure that. - Add `Logger.stdSerializers.err` serializer which is necessary to get good Error object logging with node 0.6 (where core Error object properties are non-enumerable). --- CHANGES.md | 12 +- README.md | 4 +- TODO.md | 10 +- bin/bunyan | 2 +- examples/err.js | 5 +- examples/hi.js | 4 +- lib/bunyan.js | 352 ++++++++++++++++++++++++++++-------------------- package.json | 2 +- 8 files changed, 225 insertions(+), 166 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index f5ad14f..f6b97d2 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,8 +1,16 @@ # bunyan Changelog -## bunyan 0.2.1 (not yet released) +## bunyan 0.3.0 (not yet released) + +- `log.clone` -> `log.child` to better reflect the relationship: streams and + serializers are inherited. Streams can't be removed as part of the child + creation. The child doesn't own the parent's streams (so can't close them). +- Clean up Logger creation. The goal here was to ensure `log.child` usage + is fast. TODO: measure that. +- Add `Logger.stdSerializers.err` serializer which is necessary to get good + Error object logging with node 0.6 (where core Error object properties + are non-enumerable). -(nothing yet) ## bunyan 0.2.0 diff --git a/README.md b/README.md index 676dd90..51dbe3e 100644 --- a/README.md +++ b/README.md @@ -255,8 +255,8 @@ follow (feedback from actual users welcome). Recommended/Best Practice Fields: - `err`: Object. A caught JS exception. Log that thing with - `log.error({err: err}, "oops")`! JS exceptions `JSON.stringify` quite - nicely so you don't need to do anything else. See "examples/err.js". + `log.error({err: err}, "oops")` and **use the `Logger.stdSerializers.err`** + serializer for it. See "examples/err.js". - `req_id`: String. A request identifier. Including this field in all logging tied to handling a particular request to your server is strongly suggested. This allows post analysis of logs to easily collate all related logging diff --git a/TODO.md b/TODO.md index 1a6f1b1..e0e483c 100644 --- a/TODO.md +++ b/TODO.md @@ -1,12 +1,8 @@ -- expand set of fields: from dap - time, hostname - - - require: facility and hostname - line/file: possible to get quickly with v8? Yunong asked. - fast clone: basically make it reasonable to clone per HTTP request. Ditch mutability. Add another context (another entry in Log record tuple?)? - `log.close` to close streams and shutdown and `this.closed` +- line/file: possible to get quickly with v8? Yunong asked. +- what's the API for changing the logger/stream level(s)? - bunyan cli: more layouts (http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html) Custom log formats (in config file? in '-f' arg) using printf or hogan.js or whatever. Dap wants field width control for lining up. Hogan.js is @@ -28,8 +24,6 @@ } - Logger.setLevel()? How to change level for a given stream. Default all, else, give an index... or type ... or support stream "names". -- Logger.set to mutate config or `this.fields` -- Logger.del to remove a field - "canWrite" handling for full streams. Need to buffer a la log4js - test file log with logadm rotation: does it handle that? - test suite: diff --git a/bin/bunyan b/bin/bunyan index a1fa66e..2b0f086 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,7 +5,7 @@ // See . // -var VERSION = "0.2.1"; +var VERSION = "0.3.0"; var util = require('util'); var pathlib = require('path'); diff --git a/examples/err.js b/examples/err.js index 63af6d6..b9973cc 100644 --- a/examples/err.js +++ b/examples/err.js @@ -2,12 +2,12 @@ var http = require('http'); var Logger = require('../lib/bunyan'); +var util = require('util'); var log = new Logger({ service: "myserver", serializers: { - req: Logger.stdSerializers.req, - res: Logger.stdSerializers.res + err: Logger.stdSerializers.err, // <--- use this } }); @@ -25,6 +25,7 @@ $ node err.js | ../bin/bunyan -j "hostname": "banana.local", "err": { "stack": "TypeError: boom\n at Object. (/Users/trentm/tm/node-bunyan/examples/err.js:15:9)\n at Module._compile (module.js:411:26)\n at Object..js (module.js:417:10)\n at Module.load (module.js:343:31)\n at Function._load (module.js:302:12)\n at Array.0 (module.js:430:10)\n at EventEmitter._tickCallback (node.js:126:26)", + "name": "TypeError", "message": "boom" }, "level": 4, diff --git a/examples/hi.js b/examples/hi.js index e738cb6..3f1f672 100644 --- a/examples/hi.js +++ b/examples/hi.js @@ -15,7 +15,7 @@ log.info("hi %s there", true); log.info({foo:"bar"}, "hi %d", 1, "two", 3); -// Shows `log.clone(...)` to specialize a logger for a sub-component. +// Shows `log.child(...)` to specialize a logger for a sub-component. console.log("\n\n") function Wuzzle(options) { @@ -27,7 +27,7 @@ Wuzzle.prototype.woos = function () { this.log.warn("This wuzzle is woosey.") } -var wuzzle = new Wuzzle({log: log.clone({component: "wuzzle"})}); +var wuzzle = new Wuzzle({log: log.child({component: "wuzzle"})}); wuzzle.woos(); log.info("done with the wuzzle") diff --git a/lib/bunyan.js b/lib/bunyan.js index 6c4b06f..e7a680c 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -2,7 +2,7 @@ * Copyright 2012 (c) Trent Mick. All rights reserved. */ -var VERSION = "0.2.1"; +var VERSION = "0.3.0"; // Bunyan log format version. This becomes the 'v' field on all log records. // `0` is until I release a version "1.0.0" of node-bunyan. Thereafter, @@ -28,11 +28,17 @@ var util = require('util'); //---- Internal support stuff function objCopy(obj) { - var copy = {}; - Object.keys(obj).forEach(function (k) { - copy[k] = obj[k]; - }); - return copy; + if (obj === null) { + return null; + } else if (Array.isArray(obj)) { + return obj.slice(); + } else { + var copy = {}; + Object.keys(obj).forEach(function (k) { + copy[k] = obj[k]; + }); + return copy; + } } var format = util.format; @@ -96,10 +102,14 @@ var levelFromName = { }; var nameFromLevel = [undefined].concat(Object.keys(levelFromName)); -function getLevel(nameOrNum) { - return (typeof(nameOrNum) === 'string' +function resolveLevel(nameOrNum) { + var level = (typeof(nameOrNum) === 'string' ? levelFromName[nameOrNum] : nameOrNum); + if (! (TRACE <= level && level <= FATAL)) { + throw new Error('invalid level: ' + nameOrNum); + } + return level; } @@ -110,129 +120,128 @@ function getLevel(nameOrNum) { * Create a Logger instance. * * @param options {Object} See documentation for full details. At minimum - * this must include a "service" string key. - * @param _newCloneKeys {Array} Internal var. Should not be used externally. - * Array of new keys for this clone. This is necessary to assist with - * applying necessary serializers to the new keys. + * this must include a "service" string key. Configuration keys: + * - streams: specify the logger output streams. This is an array of + * objects of the form: + * { + * "level": "info", // optional, "info" default + * "stream": process.stdout, // "stream" or "path" is required + * "closeOnExit": false // optional, default depends + * } + * See README.md for full details. + * - `level`: set the level for a single output stream (cannot be used + * with `streams`) + * - `stream`: the output stream for a logger with just one, e.g. + * `process.stdout` (cannot be used with `streams`) + * - `serializers`: object mapping log record field names to + * serializing functions. See README.md for details. + * All other keys are log record fields. + * + * An alternative *internal* call signature is used for creating a child: + * new Logger(, ); */ -function Logger(options, _newCloneKeys) { +function Logger(options, _childOptions) { xxx('Logger start:', options) if (! this instanceof Logger) { - return new Logger(options); + return new Logger(options, _childOptions); } - var self = this; + // Input arg validation. + var parent; + if (_childOptions !== undefined) { + parent = options; + options = _childOptions; + if (! parent instanceof Logger) { + throw new TypeError('invalid Logger creation: do not pass a second arg'); + } + if (options.level) { + throw new TypeError('cannot use "level" option when creating a child'); + } + if (options.stream) { + throw new TypeError('cannot use "stream" option when creating a child'); + } + } if (!options) { throw new TypeError('options (object) is required'); } - if (options.stream && options.streams) { - throw new TypeError('can only have one of "stream" or "streams"'); - } - if (_newCloneKeys && !Array.isArray(_newCloneKeys)) { - throw new TypeError('_newCloneKeys (Array) is an internal var'); + if ((options.stream || options.level) && options.streams) { + throw new TypeError('cannot mix "streams" with "stream" or "level" options'); } - // These are the default fields for log records (minus the attributes - // removed in this constructor). To allow storing raw log records - // (unrendered), `this.fields` must never be mutated. Create a copy for - // any changes. - this.fields = objCopy(options); - - // Extract and setup the configuration options (the remaining ones are - // log record fields). - var lowestLevel = Number.POSITIVE_INFINITY; - var level; - if (options.level) { - level = getLevel(options.level); - if (! (TRACE <= level && level <= FATAL)) { - throw new Error('invalid level: ' + options.level); - } - delete this.fields.level; - } else { - level = INFO; - } - - this.streams = []; - if (options.stream) { - this.streams.push({ - type: "stream", - stream: options.stream, - closeOnExit: false, - level: level + // Null values. + var self = this; + if (parent) { + this.level = parent.level; + this.streams = []; + parent.streams.forEach(function (s) { + var s = objCopy(s); + s.closeOnExit = false; // Don't own parent stream. + self.streams.push(s); }); - if (level < lowestLevel) { - lowestLevel = level; + this.serializers = objCopy(parent.serializers); + this.fields = objCopy(parent.fields); + } else { + this.level = Number.POSITIVE_INFINITY; + this.streams = []; + this.serializers = null; + this.fields = {}; + } + + // Helpers + function addStream(s) { + s = objCopy(s); + + // Implicit 'type' from other args. + type = s.type; + if (!s.type) { + if (s.stream) { + s.type = "stream"; + } else if (s.path) { + s.type = "file" + } } - delete this.fields.stream; - } else if (options.streams) { - options.streams.forEach(function (s) { - s = objCopy(s); - // Implicit 'type' from other args. - type = s.type; - if (!s.type) { - if (s.stream) { - s.type = "stream"; - } else if (s.path) { - s.type = "file" + if (s.level) { + s.level = resolveLevel(s.level); + } else { + s.level = level; + } + if (s.level < self.level) { + self.level = s.level; + } + + switch (s.type) { + case "stream": + if (!s.closeOnExit) { + s.closeOnExit = false; + } + break; + case "file": + if (!s.stream) { + s.stream = fs.createWriteStream(s.path, + {flags: 'a', encoding: 'utf8'}); + if (!s.closeOnExit) { + s.closeOnExit = true; } - } - - if (s.level) { - s.level = getLevel(s.level); } else { - s.level = level; - } - if (s.level < lowestLevel) { - lowestLevel = s.level; - } - - switch (s.type) { - case "stream": if (!s.closeOnExit) { s.closeOnExit = false; } - break; - case "file": - if (!s.stream) { - s.stream = fs.createWriteStream(s.path, - {flags: 'a', encoding: 'utf8'}); - if (!s.closeOnExit) { - s.closeOnExit = true; - } - } else { - if (!s.closeOnExit) { - s.closeOnExit = false; - } - } - break; - default: - throw new TypeError('unknown stream type "' + s.type + '"'); } - - self.streams.push(s); - }); - delete this.fields.streams; - } else { - this.streams.push({ - type: "stream", - stream: process.stdout, - closeOnExit: false, - level: level - }); - if (level < lowestLevel) { - lowestLevel = level; + break; + default: + throw new TypeError('unknown stream type "' + s.type + '"'); } + + self.streams.push(s); } - this.level = lowestLevel; - - delete this.fields.serializers; - if (!options.serializers) { - this.serializers = null; - } else { - this.serializers = {}; - Object.keys(options.serializers).forEach(function (field) { - var serializer = options.serializers[field]; + + function addSerializers(serializers) { + if (!self.serializers) { + self.serializers = {}; + } + Object.keys(serializers).forEach(function (field) { + var serializer = serializers[field]; if (typeof(serializer) !== "function") { throw new TypeError(format( 'invalid serializer for "%s" field: must be a function', field)); @@ -241,66 +250,97 @@ function Logger(options, _newCloneKeys) { } }); } - + + // Handle *config* options. + if (options.stream) { + addStream({ + type: "stream", + stream: options.stream, + closeOnExit: false, + level: (options.level ? resolveLevel(options.level) : INFO) + }); + } else if (options.streams) { + options.streams.forEach(addStream); + } else if (!parent) { + addStream({ + type: "stream", + stream: process.stdout, + closeOnExit: false, + level: (options.level ? resolveLevel(options.level) : INFO) + }); + } + if (options.serializers) { + addSerializers(options.serializers); + } xxx("Logger: ", self) - // Apply serializers to initial fields. + // Fields. + // These are the default fields for log records (minus the attributes + // removed in this constructor). To allow storing raw log records + // (unrendered), `this.fields` must never be mutated. Create a copy for + // any changes. + var fields = objCopy(options); + delete fields.stream; + delete fields.level; + delete fields.streams; + delete fields.serializers; if (this.serializers) { - if (_newCloneKeys && _newCloneKeys.length > 0) { - // Note that this includes *config* vars send to `log.clone()` in - // addition to log record *fields*, so the impl. needs to handle that. - this._applySerializers(this.fields, _newCloneKeys); - } else { - this._applySerializers(this.fields); - } + this._applySerializers(fields); } - - // Automatic fields. - if (!this.fields.hostname) { - this.fields.hostname = os.hostname(); + if (!fields.hostname) { + fields.hostname = os.hostname(); } - - //XXX Turn this on or ditch it. - //process.on('exit', function () { - // self.streams.forEach(function (s) { - // if (s.closeOnExit) { - // xxx("closing stream s:", s); - // s.stream.end(); - // } - // }); - //}); + Object.keys(fields).forEach(function (k) { + self.fields[k] = fields[k]; + }); } /** - * Clone this logger to a new one, additionally adding the given config - * options. + * Create a child logger, typically to add a few log record fields. * * This can be useful when passing a logger to a sub-component, e.g. a * "wuzzle" component of your service: * - * var wuzzleLog = log.clone({component: "wuzzle"}) + * var wuzzleLog = log.child({component: "wuzzle"}) * var wuzzle = new Wuzzle({..., log: wuzzleLog}) * * Then log records from the wuzzle code will have the same structure as * the app log, *plus the component="wuzzle" field*. * - * @param options {Object} Optional. Set of options to apply to the clone. - * Supports the same set of options as the constructor. + * @param options {Object} Optional. Set of options to apply to the child. + * All of the same options for a new Logger apply here. Notes: + * - The parent's streams are inherited and cannot be removed in this + * call. + * - The parent's serializers are inherited, though can effectively be + * overwritten by using duplicate keys. */ -Logger.prototype.clone = function (options) { - var cloneOptions = objCopy(this.fields); - cloneOptions.streams = this.streams; - if (options) { - var newCloneKeys = Object.keys(options); - newCloneKeys.forEach(function(k) { - cloneOptions[k] = options[k]; - }); - } - return new Logger(cloneOptions, newCloneKeys); +Logger.prototype.child = function (options) { + return new Logger(this, options); } +///** +// * Close this logger. +// * +// * This closes streams (that it owns, as per "endOnClose" attributes on +// * streams), etc. Typically you **don't** need to bother calling this. +// */ +//Logger.prototype.close = function () { +// if (this._closed) { +// return; +// } +// self.streams.forEach(function (s) { +// if (s.endOnClose) { +// xxx("closing stream s:", s); +// s.stream.end(); +// s.endOnClose = false; +// } +// }); +// this._closed = true; +//} + + /** * Apply registered serializers to the appropriate keys in the given fields. * @@ -607,6 +647,22 @@ Logger.stdSerializers.res = function res(res) { } }; +// Serialize an Error object +// (Core error properties are enumerable in node 0.4, not in 0.6). +Logger.stdSerializers.err = function err(err) { + var obj = { + message: err.message, + name: err.name, + stack: err.stack + } + Object.keys(err).forEach(function (k) { + if (err[k] !== undefined) { + obj[k] = err[k]; + } + }); + return obj; +}; + //---- Exports diff --git a/package.json b/package.json index b796b28..6dc54c5 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "bunyan", - "version": "0.2.1", + "version": "0.3.0", "description": "a JSON Logger library for node.js servers", "main": "./lib/bunyan.js", "bin": {