From 1a0cd4be62ce24eb4a44c9d8f299516e4ee28b63 Mon Sep 17 00:00:00 2001
From: Trent Mick <trentm@gmail.com>
Date: Mon, 6 Feb 2012 21:34:04 -0800
Subject: [PATCH] issue #2: Add guard on `JSON.stringify`ing of log records
 before emission.

---
 CHANGES.md                  | 22 ++++++++++++++++-
 examples/unstringifyable.js | 13 ++++++++++
 lib/bunyan.js               | 49 ++++++++++++++++++++++++++++++++++---
 tools/timeguard.js          | 29 ++++++++++++++++++++++
 4 files changed, 109 insertions(+), 4 deletions(-)
 create mode 100644 examples/unstringifyable.js
 create mode 100755 tools/timeguard.js

diff --git a/CHANGES.md b/CHANGES.md
index 0542b96..05b5e09 100644
--- a/CHANGES.md
+++ b/CHANGES.md
@@ -2,7 +2,27 @@
 
 ## bunyan 0.5.1 (not yet released)
 
-(nothing yet)
+- Add guard on `JSON.stringify`ing of log records before emission. This will
+  prevent `log.info` et al throwing on record fields that cannot be
+  represented as JSON. An error will be printed on stderr and a clipped
+  log record emitted with a 'bunyanMsg' key including error details. E.g.:
+  
+        bunyan: ERROR: could not stringify log record from /Users/trentm/tm/node-bunyan/examples/unstringifyable.js:12: TypeError: Converting circular structure to JSON
+        {
+          "name": "foo",
+          "hostname": "banana.local",
+          "bunyanMsg": "bunyan: ERROR: could not stringify log record from /Users/trentm/tm/node-bunyan/examples/unstringifyable.js:12: TypeError: Converting circular structure to JSON",
+        ...
+
+  Some timing shows this does effect log speed: 
+  
+        $ node tools/timeguard.js     # before
+        Time try/catch-guard on JSON.stringify:
+         - log.info:  0.07365ms per iteration
+        $ node tools/timeguard.js     # after
+        Time try/catch-guard on JSON.stringify:
+         - log.info:  0.07368ms per iteration
+  
 
 ## bunyan 0.5.0
 
diff --git a/examples/unstringifyable.js b/examples/unstringifyable.js
new file mode 100644
index 0000000..4851e59
--- /dev/null
+++ b/examples/unstringifyable.js
@@ -0,0 +1,13 @@
+// See how bunyan behaves with an un-stringify-able object.
+var Logger = require("../lib/bunyan");
+
+var log = new Logger({src: true, name: "foo"});
+
+// Make a circular object (cannot be JSON-ified).
+var myobj = {
+  foo: 'bar'
+};
+myobj.myobj = myobj;
+
+log.info({obj: myobj}, "hi there");   // <--- here
+
diff --git a/lib/bunyan.js b/lib/bunyan.js
index 43838e5..20887ed 100644
--- a/lib/bunyan.js
+++ b/lib/bunyan.js
@@ -108,6 +108,30 @@ function getCaller3Info() {
 }
 
 
+/**
+ * Warn about an bunyan processing error.
+ *
+ * If file/line are given, this makes an attempt to warn on stderr only once.
+ *
+ * @param msg {String} Message with which to warn.
+ * @param file {String} Optional. File path relevant for the warning.
+ * @param line {String} Optional. Line number in `file` path relevant for
+ *    the warning.
+ */
+function _warn(msg, file, line) {
+  assert.ok(msg);
+  var key;
+  if (file && line) {
+    key = file + ':' + line;
+    if (_warned[key]) {
+      return;
+    }
+    _warned[key] = true;
+  }
+  process.stderr.write(msg + '\n');
+}
+var _warned = {};
+
 
 
 //---- Levels
@@ -524,7 +548,7 @@ Logger.prototype._applySerializers = function (fields, keys) {
       try {
         fields[name] = self.serializers[name](fields[name]);
       } catch (err) {
-        process.stderr.write(format('bunyan: ERROR: This should never happen. '
+        _warn(format('bunyan: ERROR: This should never happen. '
           + 'This is a bug in <https://github.com/trentm/node-bunyan> or '
           + 'in this application. Exception from "%s" Logger serializer: %s',
           name, err.stack || err));
@@ -579,8 +603,27 @@ Logger.prototype._emit = function (rec) {
   }
   obj.v = LOG_VERSION;
 
-  xxx('_emit: stringify this:', obj);
-  var str = JSON.stringify(obj) + '\n';
+  // Stringify the object. Attempt to warn/recover on error.
+  var str;
+  try {
+    str = JSON.stringify(obj) + '\n';
+  } catch (e) {
+    var src = ((obj.src && obj.src.file) ? obj.src : getCaller3Info());
+    var emsg = format("bunyan: ERROR: could not stringify log record from "
+      + "%s:%d: %s", src.file, src.line, e);
+    var eobj = objCopy(rec[0]);
+    eobj.bunyanMsg = emsg;
+    eobj.msg = obj.msg;
+    eobj.time = obj.time;
+    eobj.v = LOG_VERSION;
+    _warn(emsg, src.file, src.line);
+    try {
+      str = JSON.stringify(eobj) + '\n';
+    } catch (e2) {
+      str = JSON.stringify({bunyanMsg: emsg});
+    }
+  }
+
   this.streams.forEach(function(s) {
     if (s.level <= level) {
       xxx('writing log rec "%s" to "%s" stream (%d <= %d)', obj.msg, s.type,
diff --git a/tools/timeguard.js b/tools/timeguard.js
new file mode 100755
index 0000000..7af49a1
--- /dev/null
+++ b/tools/timeguard.js
@@ -0,0 +1,29 @@
+#!/usr/bin/env node
+/*
+ * Time logging with/without a try/catch-guard on the JSON.stringify.
+ */
+
+console.log("Time try/catch-guard on JSON.stringify:");
+
+var ben = require('ben');  // npm install ben
+var Logger = require('../lib/bunyan');
+
+var records = [];
+function Collector() {
+}
+Collector.prototype.write = function(s) {
+  //records.push(s);
+}
+var collector = new Collector();
+
+var log = new Logger({
+  name: "timeguard",
+  src: true,
+  stream: collector
+});
+
+var ms = ben(1e5, function () {
+  log.info("hi");
+});
+console.log(' - log.info:  %dms per iteration', ms);
+