- 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).
This commit is contained in:
Trent Mick 2012-02-04 00:08:37 -08:00
parent d123784256
commit 6806112d8a
8 changed files with 225 additions and 166 deletions

View file

@ -1,8 +1,16 @@
# bunyan Changelog # 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 ## bunyan 0.2.0

View file

@ -255,8 +255,8 @@ follow (feedback from actual users welcome).
Recommended/Best Practice Fields: Recommended/Best Practice Fields:
- `err`: Object. A caught JS exception. Log that thing with - `err`: Object. A caught JS exception. Log that thing with
`log.error({err: err}, "oops")`! JS exceptions `JSON.stringify` quite `log.error({err: err}, "oops")` and **use the `Logger.stdSerializers.err`**
nicely so you don't need to do anything else. See "examples/err.js". serializer for it. See "examples/err.js".
- `req_id`: String. A request identifier. Including this field in all logging - `req_id`: String. A request identifier. Including this field in all logging
tied to handling a particular request to your server is strongly suggested. tied to handling a particular request to your server is strongly suggested.
This allows post analysis of logs to easily collate all related logging This allows post analysis of logs to easily collate all related logging

10
TODO.md
View file

@ -1,12 +1,8 @@
- expand set of fields: from dap
time, hostname
<https://github.com/Graylog2/graylog2-docs/wiki/GELF>
<http://journal.paul.querna.org/articles/2011/12/26/log-for-machines-in-json/>
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. - fast clone: basically make it reasonable to clone per HTTP request.
Ditch mutability. Add another context (another entry in Log record tuple?)? Ditch mutability. Add another context (another entry in Log record tuple?)?
- `log.close` to close streams and shutdown and `this.closed` - `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) - 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 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 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, - Logger.setLevel()? How to change level for a given stream. Default all,
else, give an index... or type ... or support stream "names". 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 - "canWrite" handling for full streams. Need to buffer a la log4js
- test file log with logadm rotation: does it handle that? - test file log with logadm rotation: does it handle that?
- test suite: - test suite:

View file

@ -5,7 +5,7 @@
// See <https://github.com/trentm/node-bunyan>. // See <https://github.com/trentm/node-bunyan>.
// //
var VERSION = "0.2.1"; var VERSION = "0.3.0";
var util = require('util'); var util = require('util');
var pathlib = require('path'); var pathlib = require('path');

View file

@ -2,12 +2,12 @@
var http = require('http'); var http = require('http');
var Logger = require('../lib/bunyan'); var Logger = require('../lib/bunyan');
var util = require('util');
var log = new Logger({ var log = new Logger({
service: "myserver", service: "myserver",
serializers: { serializers: {
req: Logger.stdSerializers.req, err: Logger.stdSerializers.err, // <--- use this
res: Logger.stdSerializers.res
} }
}); });
@ -25,6 +25,7 @@ $ node err.js | ../bin/bunyan -j
"hostname": "banana.local", "hostname": "banana.local",
"err": { "err": {
"stack": "TypeError: boom\n at Object.<anonymous> (/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)", "stack": "TypeError: boom\n at Object.<anonymous> (/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" "message": "boom"
}, },
"level": 4, "level": 4,

View file

@ -15,7 +15,7 @@ log.info("hi %s there", true);
log.info({foo:"bar"}, "hi %d", 1, "two", 3); 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") console.log("\n\n")
function Wuzzle(options) { function Wuzzle(options) {
@ -27,7 +27,7 @@ Wuzzle.prototype.woos = function () {
this.log.warn("This wuzzle is woosey.") 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(); wuzzle.woos();
log.info("done with the wuzzle") log.info("done with the wuzzle")

View file

@ -2,7 +2,7 @@
* Copyright 2012 (c) Trent Mick. All rights reserved. * 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. // 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, // `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 //---- Internal support stuff
function objCopy(obj) { function objCopy(obj) {
var copy = {}; if (obj === null) {
Object.keys(obj).forEach(function (k) { return null;
copy[k] = obj[k]; } else if (Array.isArray(obj)) {
}); return obj.slice();
return copy; } else {
var copy = {};
Object.keys(obj).forEach(function (k) {
copy[k] = obj[k];
});
return copy;
}
} }
var format = util.format; var format = util.format;
@ -96,10 +102,14 @@ var levelFromName = {
}; };
var nameFromLevel = [undefined].concat(Object.keys(levelFromName)); var nameFromLevel = [undefined].concat(Object.keys(levelFromName));
function getLevel(nameOrNum) { function resolveLevel(nameOrNum) {
return (typeof(nameOrNum) === 'string' var level = (typeof(nameOrNum) === 'string'
? levelFromName[nameOrNum] ? levelFromName[nameOrNum]
: 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. * Create a Logger instance.
* *
* @param options {Object} See documentation for full details. At minimum * @param options {Object} See documentation for full details. At minimum
* this must include a "service" string key. * this must include a "service" string key. Configuration keys:
* @param _newCloneKeys {Array} Internal var. Should not be used externally. * - streams: specify the logger output streams. This is an array of
* Array of new keys for this clone. This is necessary to assist with * objects of the form:
* applying necessary serializers to the new keys. * {
* "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(<parent logger>, <child options>);
*/ */
function Logger(options, _newCloneKeys) { function Logger(options, _childOptions) {
xxx('Logger start:', options) xxx('Logger start:', options)
if (! this instanceof Logger) { 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) { if (!options) {
throw new TypeError('options (object) is required'); throw new TypeError('options (object) is required');
} }
if (options.stream && options.streams) { if ((options.stream || options.level) && options.streams) {
throw new TypeError('can only have one of "stream" or "streams"'); throw new TypeError('cannot mix "streams" with "stream" or "level" options');
}
if (_newCloneKeys && !Array.isArray(_newCloneKeys)) {
throw new TypeError('_newCloneKeys (Array) is an internal var');
} }
// These are the default fields for log records (minus the attributes // Null values.
// removed in this constructor). To allow storing raw log records var self = this;
// (unrendered), `this.fields` must never be mutated. Create a copy for if (parent) {
// any changes. this.level = parent.level;
this.fields = objCopy(options); this.streams = [];
parent.streams.forEach(function (s) {
// Extract and setup the configuration options (the remaining ones are var s = objCopy(s);
// log record fields). s.closeOnExit = false; // Don't own parent stream.
var lowestLevel = Number.POSITIVE_INFINITY; self.streams.push(s);
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
}); });
if (level < lowestLevel) { this.serializers = objCopy(parent.serializers);
lowestLevel = level; 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. if (s.level) {
type = s.type; s.level = resolveLevel(s.level);
if (!s.type) { } else {
if (s.stream) { s.level = level;
s.type = "stream"; }
} else if (s.path) { if (s.level < self.level) {
s.type = "file" 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 { } else {
s.level = level;
}
if (s.level < lowestLevel) {
lowestLevel = s.level;
}
switch (s.type) {
case "stream":
if (!s.closeOnExit) { if (!s.closeOnExit) {
s.closeOnExit = false; 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 + '"');
} }
break;
self.streams.push(s); default:
}); throw new TypeError('unknown stream type "' + s.type + '"');
delete this.fields.streams;
} else {
this.streams.push({
type: "stream",
stream: process.stdout,
closeOnExit: false,
level: level
});
if (level < lowestLevel) {
lowestLevel = level;
} }
self.streams.push(s);
} }
this.level = lowestLevel;
function addSerializers(serializers) {
delete this.fields.serializers; if (!self.serializers) {
if (!options.serializers) { self.serializers = {};
this.serializers = null; }
} else { Object.keys(serializers).forEach(function (field) {
this.serializers = {}; var serializer = serializers[field];
Object.keys(options.serializers).forEach(function (field) {
var serializer = options.serializers[field];
if (typeof(serializer) !== "function") { if (typeof(serializer) !== "function") {
throw new TypeError(format( throw new TypeError(format(
'invalid serializer for "%s" field: must be a function', field)); '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) 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 (this.serializers) {
if (_newCloneKeys && _newCloneKeys.length > 0) { this._applySerializers(fields);
// 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);
}
} }
if (!fields.hostname) {
// Automatic fields. fields.hostname = os.hostname();
if (!this.fields.hostname) {
this.fields.hostname = os.hostname();
} }
Object.keys(fields).forEach(function (k) {
//XXX Turn this on or ditch it. self.fields[k] = fields[k];
//process.on('exit', function () { });
// self.streams.forEach(function (s) {
// if (s.closeOnExit) {
// xxx("closing stream s:", s);
// s.stream.end();
// }
// });
//});
} }
/** /**
* Clone this logger to a new one, additionally adding the given config * Create a child logger, typically to add a few log record fields.
* options.
* *
* This can be useful when passing a logger to a sub-component, e.g. a * This can be useful when passing a logger to a sub-component, e.g. a
* "wuzzle" component of your service: * "wuzzle" component of your service:
* *
* var wuzzleLog = log.clone({component: "wuzzle"}) * var wuzzleLog = log.child({component: "wuzzle"})
* var wuzzle = new Wuzzle({..., log: wuzzleLog}) * var wuzzle = new Wuzzle({..., log: wuzzleLog})
* *
* Then log records from the wuzzle code will have the same structure as * Then log records from the wuzzle code will have the same structure as
* the app log, *plus the component="wuzzle" field*. * the app log, *plus the component="wuzzle" field*.
* *
* @param options {Object} Optional. Set of options to apply to the clone. * @param options {Object} Optional. Set of options to apply to the child.
* Supports the same set of options as the constructor. * 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) { Logger.prototype.child = function (options) {
var cloneOptions = objCopy(this.fields); return new Logger(this, options);
cloneOptions.streams = this.streams;
if (options) {
var newCloneKeys = Object.keys(options);
newCloneKeys.forEach(function(k) {
cloneOptions[k] = options[k];
});
}
return new Logger(cloneOptions, newCloneKeys);
} }
///**
// * 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. * 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 //---- Exports

View file

@ -1,6 +1,6 @@
{ {
"name": "bunyan", "name": "bunyan",
"version": "0.2.1", "version": "0.3.0",
"description": "a JSON Logger library for node.js servers", "description": "a JSON Logger library for node.js servers",
"main": "./lib/bunyan.js", "main": "./lib/bunyan.js",
"bin": { "bin": {