From 550ea90e1c2f8baed79881e85bc79a089d2abc1c Mon Sep 17 00:00:00 2001 From: Todd Whiteman Date: Wed, 1 Mar 2017 16:33:30 -0800 Subject: [PATCH] Bunyan's `safeCycles` is too slow when logging large objects. Fixes #474 --- CHANGES.md | 5 +++ bin/bunyan | 2 +- lib/bunyan.js | 92 ++++++++++++++++++++++++++++++++++++++------------- package.json | 2 +- 4 files changed, 76 insertions(+), 25 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index 01f378a..1502488 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -8,6 +8,11 @@ Known issues: ## not yet released +## 1.8.6 + +- [issue #474] Bunyan's `safeCycles` is too slow when logging large objects. + + ## 1.8.5 - [issue #401] Improved performance when using disabled log levels. diff --git a/bin/bunyan b/bin/bunyan index a1c3851..d8112ad 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -11,7 +11,7 @@ * vim: expandtab:ts=4:sw=4 */ -var VERSION = '1.8.5'; +var VERSION = '1.8.6'; var p = console.log; var util = require('util'); diff --git a/lib/bunyan.js b/lib/bunyan.js index 778c919..6ed9e8a 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -8,7 +8,7 @@ * vim: expandtab:ts=4:sw=4 */ -var VERSION = '1.8.5'; +var VERSION = '1.8.6'; /* * Bunyan log format version. This becomes the 'v' field on all log records. @@ -155,7 +155,7 @@ if (!format) { switch (x) { case '%s': return String(args[i++]); case '%d': return Number(args[i++]); - case '%j': return JSON.stringify(args[i++], safeCycles()); + case '%j': return fastAndSafeJsonStringify(args[i++]); case '%%': return '%'; default: return x; @@ -905,26 +905,10 @@ Logger.prototype._emit = function (rec, noemit) { } } - // Stringify the object. Attempt to warn/recover on error. + // Stringify the object (creates a warning str on error). var str; if (noemit || this.haveNonRawStreams) { - try { - str = JSON.stringify(rec, safeCycles()) + '\n'; - } catch (e) { - if (safeJsonStringify) { - str = safeJsonStringify(rec) + '\n'; - } else { - var dedupKey = e.stack.split(/\n/g, 2).join('\n'); - _warn('bunyan: ERROR: Exception in ' - + '`JSON.stringify(rec)`. You can install the ' - + '"safe-json-stringify" module to have Bunyan fallback ' - + 'to safer stringification. Record:\n' - + _indent(format('%s\n%s', util.inspect(rec), e.stack)), - dedupKey); - str = format('(Exception in JSON.stringify(rec): %j. ' - + 'See stderr for details.)\n', e.message); - } - } + str = fastAndSafeJsonStringify(rec) + '\n'; } if (noemit) @@ -1168,9 +1152,30 @@ var errSerializer = Logger.stdSerializers.err = function err(err) { }; -// A JSON stringifier that handles cycles safely. -// Usage: JSON.stringify(obj, safeCycles()) -function safeCycles() { +// A JSON stringifier that handles cycles safely - tracks seen values in a Set. +function safeCyclesSet() { + var seen = new Set(); + return function (key, val) { + if (!val || typeof (val) !== 'object') { + return val; + } + if (seen.has(val)) { + return '[Circular]'; + } + seen.add(val); + return val; + }; +} + +/** + * A JSON stringifier that handles cycles safely - tracks seen vals in an Array. + * + * Note: This approach has performance problems when dealing with large objects, + * see trentm/node-bunyan#445, but since this is the only option for node 0.10 + * and earlier (as Set was introduced in Node 0.12), it's used as a fallback + * when Set is not available. + */ +function safeCyclesArray() { var seen = []; return function (key, val) { if (!val || typeof (val) !== 'object') { @@ -1184,6 +1189,47 @@ function safeCycles() { }; } +/** + * A JSON stringifier that handles cycles safely. + * + * Usage: JSON.stringify(obj, safeCycles()) + * + * Choose the best safe cycle function from what is available - see + * trentm/node-bunyan#445. + */ +var safeCycles = Set ? safeCyclesSet : safeCyclesArray; + +/** + * A fast JSON.stringify that handles cycles and getter exceptions (when + * safeJsonStringify is installed). + * + * This function attempts to use the regular JSON.stringify for speed, but on + * error (e.g. JSON cycle detection exception) it falls back to safe stringify + * handlers that can deal with cycles and/or getter exceptions. + */ +function fastAndSafeJsonStringify(rec) { + try { + return JSON.stringify(rec); + } catch (ex) { + try { + return JSON.stringify(rec, safeCycles()); + } catch (e) { + if (safeJsonStringify) { + return safeJsonStringify(rec); + } else { + var dedupKey = e.stack.split(/\n/g, 3).join('\n'); + _warn('bunyan: ERROR: Exception in ' + + '`JSON.stringify(rec)`. You can install the ' + + '"safe-json-stringify" module to have Bunyan fallback ' + + 'to safer stringification. Record:\n' + + _indent(format('%s\n%s', util.inspect(rec), e.stack)), + dedupKey); + return format('(Exception in JSON.stringify(rec): %j. ' + + 'See stderr for details.)', e.message); + } + } + } +} var RotatingFileStream = null; diff --git a/package.json b/package.json index 260c1a2..ec66b2e 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "bunyan", - "version": "1.8.5", + "version": "1.8.6", "description": "a JSON logging library for node.js services", "author": "Trent Mick (http://trentm.com)", "main": "./lib/bunyan.js",