OS-2030, smartos-live #184: fix serializer bug added in bunyan 0.18.3

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 <https://github.com/trentm/node-bunyan> 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

bin/bunyan

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

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]) {
+    if (fields[name] === undefined
-      xxx('_applySerializers; apply to "%s" key', name)
+        || (excludeFields && excludeFields[name])) {
-      try {
+      return;
-        fields[name] = self.serializers[name](fields[name]);
+    }
-      } catch (err) {
+    xxx('_applySerializers; apply to "%s" key', name)
-        _warn(format('bunyan: ERROR: This should never happen. '
+    try {
-          + 'This is a bug in <https://github.com/trentm/node-bunyan> or '
+      fields[name] = self.serializers[name](fields[name]);
-          + 'in this application. Exception from "%s" Logger serializer: %s',
+    } catch (err) {
-          name, err.stack || err));
+      _warn(format('bunyan: ERROR: This should never happen. '
-        fields[name] = format('(Error in Bunyan log "%s" serializer '
+        + 'This is a bug in <https://github.com/trentm/node-bunyan> or '
-          + 'broke field. See stderr for details.)', name);
+        + '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);
     }
   });
 }

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 <trentm@gmail.com> (http://trentm.com)",
   "main": "./lib/bunyan.js",

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();
 });