diff --git a/README.md b/README.md index 8d9e4cb..cfcc6ae 100644 --- a/README.md +++ b/README.md @@ -90,7 +90,49 @@ same config as its parent, plus include the "component" field. log.info("done with the wuzzle") +Back to the `log.{trace|debug|...|fatal}(...)` API: + log.info(); // returns a boolean: is the "info" level enabled? + log.info("hi"); // log a simple string message + log.info("hi %s", bob, anotherVar); // uses `util.format` for msg formatting + log.info({foo: "bar"}, "hi"); // adds "foo" field to log record + +Bunyan has a concept of **"serializers" to produce a JSON-able object from a +JavaScript object**, so your can easily do the following: + + log.info({req: }, "something about handling this request"); + +Association is by log record field name, "req" in this example, so this +requires a registered serializer something like this: + + function reqSerializer(req) { + return { + method: req.method, + url: req.url, + headers: req.headers + } + } + var log = new Logger({ + ... + serializers: { + req: reqSerializer + } + }); + +Or this: + + var log = new Logger({ + ... + serializers: {req: Logger.stdSerializers.req} + }); + +because Buyan includes a small set of standard serializers. To use all the +standard serializers you can use: + + var log = new Logger({ + ... + serializers: Logger.stdSerializers + }); # Future diff --git a/TODO.md b/TODO.md index 123dbf9..0551677 100644 --- a/TODO.md +++ b/TODO.md @@ -1,7 +1,12 @@ -- serializer support (i.e. repr of a restify request obj): - server.js example - restify-server.js example -- 'x' extra fields object or no? discuss +- serializer support: + - Ask mark what else to put in `req` + - Ask mark what to put in `res` + - restify-server.js example -> restifyReq ? or have `req` detect that. + That is nicer for the "use all standard ones". *Does* restify req + have anything special? + - Add `err`. + - `request_id` that pulls it from req? `log.info({request_id: req}, "hi")` +- `log.close` to close streams and shutdown and `this.closed` - expand set of fields: from dap time, hostname @@ -32,10 +37,13 @@ - 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: - test for a cloned logger double-`stream.end()` causing problems. Perhaps the "closeOnExit" for existing streams should be false for clones. + - test that a `log.clone(...)` adding a new field matching a serializer + works *and* that an existing field in the parent is not *re-serialized*. - a "rolling-file" stream: but specifically by time, e.g. hourly. (MarkC requested) diff --git a/examples/server.js b/examples/server.js new file mode 100644 index 0000000..219afec --- /dev/null +++ b/examples/server.js @@ -0,0 +1,30 @@ +var http = require('http'); +var Logger = require('../lib/bunyan'); + +// Basic usage. +var log = new Logger({ + service: "myserver", + serializers: {req: Logger.stdSerializers.req} +}); + +http.createServer(function (req, res) { + log.info({req: req}, "start request"); // <-- this is the guy we're testing + res.writeHead(200, {'Content-Type': 'text/plain'}); + res.end('Hello World\n'); +}).listen(1337, "127.0.0.1", function () { + log.info("server listening"); + var options = { + port: 1337, + host: '127.0.0.1', + headers: { + 'X-Hi': 'Mom' + } + }; + var req = http.request(options); + req.on('response', function (res) { + res.on('end', function () { + process.exit(); + }) + }); + req.end(); +}); diff --git a/lib/bunyan.js b/lib/bunyan.js index 1bf7cac..519aba4 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -11,7 +11,7 @@ var LOG_VERSION = 0; var xxx = function xxx(s) { // internal dev/debug logging - var args = ["PAUL: "+s].concat(Array.prototype.slice.call(arguments, 1)); + var args = ['XX' + 'X: '+s].concat(Array.prototype.slice.call(arguments, 1)); console.error.apply(this, args); }; var xxx = function xxx() {}; // uncomment to turn of debug logging @@ -101,10 +101,20 @@ function getLevel(nameOrNum) { } + //---- Logger class -function Logger(options) { - paul('Logger start:', options) +/** + * 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. + */ +function Logger(options, _newCloneKeys) { + xxx('Logger start:', options) if (! this instanceof Logger) { return new Logger(options); } @@ -116,6 +126,9 @@ function Logger(options) { 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'); + } // These are the default fields for log records (minus the attributes // removed in this constructor). To allow storing raw log records @@ -136,6 +149,7 @@ function Logger(options) { } else { level = INFO; } + this.streams = []; if (options.stream) { this.streams.push({ @@ -210,15 +224,41 @@ function Logger(options) { } 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]; + if (typeof(serializer) !== "function") { + throw new TypeError(format( + 'invalid serializer for "%s" field: must be a function', field)); + } else { + self.serializers[field] = serializer; + } + }); + } + xxx("Logger: ", self) + // Apply serializers to initial fields. + 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); + } + } + // Automatic fields. if (!this.fields.hostname) { this.fields.hostname = os.hostname(); } - //XXX Non-core fields should go in 'x' sub-object. - + //XXX Turn this on or ditch it. //process.on('exit', function () { // self.streams.forEach(function (s) { // if (s.closeOnExit) { @@ -250,11 +290,54 @@ Logger.prototype.clone = function (options) { var cloneOptions = objCopy(this.fields); cloneOptions.streams = this.streams; if (options) { - Object.keys(options).forEach(function(k) { + var newCloneKeys = Object.keys(options); + newCloneKeys.forEach(function(k) { cloneOptions[k] = options[k]; }); } - return new Logger(cloneOptions); + return new Logger(cloneOptions, newCloneKeys); +} + + +/** + * Apply registered serializers to the appropriate keys in the given fields. + * + * Pre-condition: This is only called if there is at least one serializer. + * + * @param fields (Object) The log record fields. + * @param keys (Array) Optional array of keys to which to limit processing. + */ +Logger.prototype._applySerializers = function (fields, keys) { + var self = this; + + // Mapping of keys to potentially serialize. + var applyKeys = fields; + if (keys) { + applyKeys = {}; + for (var i=0; i < keys.length; i++) { + applyKeys[keys[i]] = true; + } + } + + xxx('_applySerializers: applyKeys', applyKeys); + + // Check each serializer against these (presuming number of serializers + // is typically less than number of fields). + Object.keys(this.serializers).forEach(function (name) { + if (applyKeys[name]) { + xxx('_applySerializers; apply to "%s" key', name) + try { + fields[name] = self.serializers[name](fields[name]); + } catch (err) { + process.stderr.write(format('bunyan: ERROR: This should never happen. ' + + 'This is a bug in or ' + + 'in this application. Exception from "%s" Logger serializer: %s', + name, err.stack || err)); + fields[name] = format('(Error in Bunyan log "%s" serializer ' + + 'broke field. See stderr for details.)', name); + } + } + }); } @@ -282,6 +365,9 @@ Logger.prototype._emit = function (rec) { var obj = objCopy(rec[0]); var recFields = rec[1]; if (recFields) { + if (this.serializers) { + this._applySerializers(recFields); + } Object.keys(recFields).forEach(function (k) { obj[k] = recFields[k]; }); @@ -294,6 +380,7 @@ Logger.prototype._emit = function (rec) { } obj.v = LOG_VERSION; + xxx('_emit: stringify this:', obj); var str = JSON.stringify(obj) + '\n'; this.streams.forEach(function(s) { if (s.level <= level) { @@ -486,6 +573,29 @@ Logger.prototype.fatal = function () { } + +//---- Standard serializers +// A serializer is a function that serializes a JavaScript object to a +// JSON representation for logging. There is a standard set of presumed +// interesting objects in node.js-land. + +Logger.stdSerializers = {}; + +// Serialize an HTTP request. +Logger.stdSerializers.req = function req(req) { + return { + method: req.method, + url: req.url, + headers: req.headers + } +}; + + + + + +//---- Exports + module.exports = Logger;