From 1a8be0c1e6a5b436bfdfcd6224a225b48ea061a6 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Fri, 15 Mar 2013 11:25:56 -0700 Subject: [PATCH] OS-2030, smartos-live #184: fix serializer bug added in bunyan 0.18.3 --- CHANGES.md | 33 ++++++++++++++++++- bin/bunyan | 2 +- lib/bunyan.js | 30 +++++++++-------- package.json | 2 +- ...erializers.test.js => serializers.test.js} | 30 +++++++++++++++++ 5 files changed, 80 insertions(+), 17 deletions(-) rename test/{std-serializers.test.js => serializers.test.js} (89%) diff --git a/CHANGES.md b/CHANGES.md index 82c54b2..723542a 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -6,7 +6,16 @@ Known issues: bug](https://github.com/TooTallNate/node-gyp/issues/65). -## bunyan 0.19.1 (not yet released) +## bunyan 0.20.0 (not yet released) + +- [Slight backward incompatibility] Fix serializer bug introduced in 0.18.3 + (see below) to only apply serializers to log records when appropriate. + + This also makes a semantic change to custom serializers. Before this change + a serializer function was called for a log record key when that value was + truth-y. The semantic change is to call the serializer function as long + as the value is not `undefined`. That means that a serializer function + should handle falsey values such as `false` and `null`. - Update to latest 'mv' dep (required for rotating-file support) to support node v0.10.0. @@ -14,6 +23,9 @@ Known issues: ## bunyan 0.19.0 +**WARNING**: This release includes a bug introduced in bunyan 0.18.3 (see +below). Please upgrade to bunyan 0.20.0. + - [Slight backward incompatibility] Change the default error serialization (a.k.a. `bunyan.stdSerializers.err`) to *not* serialize all additional attributes of the given error object. This is an open door to unsafe logging @@ -66,6 +78,25 @@ Known issues: ## bunyan 0.18.3 +**WARNING**: This release introduced a bug such that all serializers are +applied to all log records even if the log record did not contain the key +for that serializer. If a logger serializer function does not handle +being given `undefined`, then you'll get warnings like this on stderr: + + bunyan: ERROR: This should never happen. This is a bug in or in this application. Exception from "foo" Logger serializer: Error: ... + at Object.bunyan.createLogger.serializers.foo (.../myapp.js:20:15) + at Logger._applySerializers (.../lib/bunyan.js:644:46) + at Array.forEach (native) + at Logger._applySerializers (.../lib/bunyan.js:640:33) + ... + +and the following junk in written log records: + + "foo":"(Error in Bunyan log "foo" serializer broke field. See stderr for details.)" + +Please upgrade to bunyan 0.20.0. + + - Change the `bunyan.stdSerializers.err` serializer for errors to *exclude* [the "domain*" keys](http://nodejs.org/docs/latest/api/all.html#all_additions_to_error_objects). `err.domain` will include its assigned members which can arbitrarily large diff --git a/bin/bunyan b/bin/bunyan index 98e41e3..c13f65e 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,7 +5,7 @@ // See . // -var VERSION = "0.19.1"; +var VERSION = "0.20.0"; var util = require('util'); var pathlib = require('path'); diff --git a/lib/bunyan.js b/lib/bunyan.js index 6fffa76..611ad11 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -4,7 +4,7 @@ * The bunyan logging library for node.js. */ -var VERSION = '0.19.1'; +var VERSION = '0.20.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, @@ -18,7 +18,7 @@ var xxx = function xxx(s) { // internal dev/debug logging 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 +var xxx = function xxx() {}; // comment out to turn on debug logging var os = require('os'); @@ -638,18 +638,20 @@ Logger.prototype._applySerializers = function (fields, excludeFields) { // Check each serializer against these (presuming number of serializers // is typically less than number of fields). Object.keys(this.serializers).forEach(function (name) { - if (!excludeFields || !excludeFields[name]) { - xxx('_applySerializers; apply to "%s" key', name) - try { - fields[name] = self.serializers[name](fields[name]); - } catch (err) { - _warn(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); - } + if (fields[name] === undefined + || (excludeFields && excludeFields[name])) { + return; + } + xxx('_applySerializers; apply to "%s" key', name) + try { + fields[name] = self.serializers[name](fields[name]); + } catch (err) { + _warn(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); } }); } diff --git a/package.json b/package.json index 193e8fe..52eed6e 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "bunyan", - "version": "0.19.1", + "version": "0.20.0", "description": "a JSON Logger library for node.js services", "author": "Trent Mick (http://trentm.com)", "main": "./lib/bunyan.js", diff --git a/test/std-serializers.test.js b/test/serializers.test.js similarity index 89% rename from test/std-serializers.test.js rename to test/serializers.test.js index e6300fb..d4b5a78 100644 --- a/test/std-serializers.test.js +++ b/test/serializers.test.js @@ -258,6 +258,36 @@ test('err serializer: long stack', function (t) { + '\nCaused by: ' + bottomErr.stack); t.equal(lastRecord.err.stack, expectedStack, 'WError <- WError <- WError'); + t.end(); +}); + + +// Bunyan 0.18.3 introduced a bug where *all* serializers are applied +// even if the log record doesn't have the associated key. That means +// serializers that don't handle an `undefined` value will blow up. +test('do not apply serializers if no record key', function (t) { + var records = []; + var log = bunyan.createLogger({ + name: 'serializer-test', + streams: [{ + stream: new CapturingStream(records), + type: 'raw' + }], + serializers: { + err: bunyan.stdSerializers.err, + boom: function (value) { + throw new Error('boom'); + } + } + }); + + log.info({foo: 'bar'}, 'record one'); + log.info({err: new Error('record two err')}, 'record two'); + + t.equal(records[0].boom, undefined); + t.equal(records[0].foo, 'bar'); + t.equal(records[1].boom, undefined); + t.equal(records[1].err.message, 'record two err'); t.end(); });