Repository: luin/ioredis
Pull request #523 (2017-09-25 09:52:27)

truncate large/long debug output arguments
wrap the debug node_module so that large/long debug output args are always truncated (avoids potentially MBs of data being outout to console).

this PR adds a module that offers a transparent wrap for the 3rd-party `debug` module, 
you just need to require `./utils/debug` in place of `debug` itself.

the idea for this PR was originally discussed here: https://github.com/luin/ioredis/issues/521

there are a couple of unit tests included.

luin: Nice patch! However, it seems that these changes may have a impact on the performance even when the debug mode is off (e.g. truncating strings).

I just found out that the debug module supports custom formatters. What about define a custom formatter for the arguments?

For example:

```
const createDebug = require('debug');
createDebug.formatters.a = (v) => {
  return genRedactedString(v, len);
};

module.exports = createDebug;
iamjochem: you are correct about the custom formatters - this is what I actually currently use to solve this issue in my own project. 

the reason I chose not to use custom formatters here is because they are applied "module" wide ... i.e. you may very well be overriding existing custom formatters or applying them (without asking) to all instances of "debug" used in a project's own code and all it's other dependencies (assuming they use the same version) ... I felt that this was something to be avoided (it is unfortunate that `debug` does not support custom formatters per 'instance')

the fix for the potential performance hit is easy enough - I pushed a commit that make the debug call a no-op (basically performing the same check as is done in the `debug` module itself) ... what do think? 
luin: Awesome! Makes sense to me. I'll do some tests this weekend, and merge then.

Patch:
diff --git a/lib/cluster/delay_queue.js b/lib/cluster/delay_queue.js
index 5d6696b..b93e6dd 100644
--- a/lib/cluster/delay_queue.js
+++ b/lib/cluster/delay_queue.js
@@ -1,7 +1,7 @@
 'use strict';
 
 var Deque = require('denque');
-var debug = require('debug')('ioredis:delayqueue');
+var debug = require('../utils/debug')('ioredis:delayqueue');
 
 function DelayQueue() {
   this.queues = {};
diff --git a/lib/cluster/index.js b/lib/cluster/index.js
index 0203946..c268c88 100644
--- a/lib/cluster/index.js
+++ b/lib/cluster/index.js
@@ -6,7 +6,7 @@ var Redis = require('../redis');
 var utils = require('../utils');
 var util = require('util');
 var EventEmitter = require('events').EventEmitter;
-var debug = require('debug')('ioredis:cluster');
+var debug = require('../utils/debug')('ioredis:cluster');
 var _ = require('../utils/lodash');
 var ScanStream = require('../scan_stream');
 var Commander = require('../commander');
diff --git a/lib/connectors/sentinel_connector.js b/lib/connectors/sentinel_connector.js
index e039874..f133d06 100644
--- a/lib/connectors/sentinel_connector.js
+++ b/lib/connectors/sentinel_connector.js
@@ -5,7 +5,7 @@ var util = require('util');
 var net = require('net');
 var utils = require('../utils');
 var Connector = require('./connector');
-var debug = require('debug')('ioredis:SentinelConnector');
+var debug = require('../utils/debug')('ioredis:SentinelConnector');
 var Redis;
 
 function SentinelConnector(options) {
diff --git a/lib/redis.js b/lib/redis.js
index d064f35..381e7e1 100644
--- a/lib/redis.js
+++ b/lib/redis.js
@@ -9,7 +9,7 @@ var Command = require('./command');
 var Commander = require('./commander');
 var utils = require('./utils');
 var eventHandler = require('./redis/event_handler');
-var debug = require('debug')('ioredis:redis');
+var debug = require('./utils/debug')('ioredis:redis');
 var Connector = require('./connectors/connector');
 var SentinelConnector = require('./connectors/sentinel_connector');
 var ScanStream = require('./scan_stream');
diff --git a/lib/redis/event_handler.js b/lib/redis/event_handler.js
index de24259..4345eff 100644
--- a/lib/redis/event_handler.js
+++ b/lib/redis/event_handler.js
@@ -1,6 +1,6 @@
 'use strict';
 
-var debug = require('debug')('ioredis:connection');
+var debug = require('../utils/debug')('ioredis:connection');
 var Command = require('../command');
 var utils = require('../utils');
 var _ = require('../utils/lodash');
diff --git a/lib/redis/parser.js b/lib/redis/parser.js
index 8b9788f..0d79416 100644
--- a/lib/redis/parser.js
+++ b/lib/redis/parser.js
@@ -3,7 +3,7 @@
 var _ = require('../utils/lodash');
 var Command = require('../command');
 var SubscriptionSet = require('../subscription_set');
-var debug = require('debug')('ioredis:reply');
+var debug = require('../utils/debug')('ioredis:reply');
 var Parser = require('redis-parser');
 var ReplyError = require('../reply_error');
 
diff --git a/lib/utils/debug.js b/lib/utils/debug.js
new file mode 100644
index 0000000..0e96b04
--- /dev/null
+++ b/lib/utils/debug.js
@@ -0,0 +1,117 @@
+var debug = require('debug');
+
+var MAX_ARGUMENT_LENGTH = 200;
+
+/**
+ * helper function that tried to get a string value for
+ * arbitrary "debug" arg
+ *
+ * @param  {mixed} v
+ * @return {String|undefined}
+ */
+function getStringValue(v) {
+  if (v === null)
+    return;
+
+  switch (typeof v) {
+  case 'boolean': return;
+  case 'number': return;
+
+  case 'object':
+    if (Buffer.isBuffer(v)) {
+      return v.toString('hex');
+    }
+
+    if (Array.isArray(v)) {
+      return v.join(',');
+    }
+
+    try {
+      return JSON.stringify(v);
+    } catch (e) {
+      return;
+    }
+
+  case 'string': return v;
+  }
+}
+
+/**
+ * helper function that redacts a string representation of a "debug" arg
+ *
+ * @param  {String} str
+ * @param  {Number} max_len
+ * @return {String}
+ */
+function genRedactedString(str, max_len) {
+  var len = str.length;
+
+  return len <= max_len ? str : str.slice(0, max_len) + ' ... <REDACTED full-length="' + len + '">';
+}
+
+/**
+ * a wrapper for the `debug` module, used to generate
+ * "debug functions" that trim the values in their output
+ *
+ * @param   {String}
+ * @return  {Function}
+ */
+module.exports = function genDebugFunction(name) {
+
+  var fn = debug(name);
+
+  function wrappedDebug() {
+    if (!fn.enabled) {
+      return; // no-op
+    }
+
+    var args = [].slice.call(arguments);
+    var i = 1, l = args.length, str, len;
+
+    // we skip the first arg because that is the message
+    for (; i < l; i += 1) {
+      str = getStringValue(args[i]);
+      len = str && str.length || 0;
+
+      if (len > MAX_ARGUMENT_LENGTH) {
+        args[i] = genRedactedString(str, MAX_ARGUMENT_LENGTH);
+      }
+    }
+
+    return fn.apply(null, args);
+  }
+
+  Object.defineProperties(wrappedDebug, {
+    namespace: { get: function () {
+      return fn.namespace;
+    } },
+    enabled: { get: function () {
+      return fn.enabled;
+    } },
+    useColors: { get: function () {
+      return fn.useColors;
+    } },
+    color: { get: function () {
+      return fn.color;
+    } },
+    destroy: { get: function () {
+      return fn.destroy;
+    } },
+    log: {
+      get: function () {
+        return fn.log;
+      },
+      set: function (l) {
+        fn.log = l;
+      }
+    }
+
+  });
+
+  return wrappedDebug;
+};
+
+// expose private stuff for unit-testing
+module.exports.MAX_ARGUMENT_LENGTH = MAX_ARGUMENT_LENGTH;
+module.exports.getStringValue = getStringValue;
+module.exports.genRedactedString = genRedactedString;


Test patch:
diff --git a/test/unit/debug.js b/test/unit/debug.js
new file mode 100644
index 0000000..8ff60b6
--- /dev/null
+++ b/test/unit/debug.js
@@ -0,0 +1,78 @@
+'use strict';
+
+var real_debug = require('debug');
+
+var debug = require('../../lib/utils/debug');
+
+describe('utils/debug', function () {
+
+  afterEach(function () {
+    real_debug.enable(process.env.DEBUG || '');
+  });
+
+  describe('.exports.getStringValue', function () {
+    it('should return a string or undefined', function () {
+      expect(debug.getStringValue(true)).to.be.undefined;
+      expect(debug.getStringValue(undefined)).to.be.undefined;
+      expect(debug.getStringValue(null)).to.be.undefined;
+      expect(debug.getStringValue(false)).to.be.undefined;
+      expect(debug.getStringValue(1)).to.be.undefined;
+      expect(debug.getStringValue(1.1)).to.be.undefined;
+      expect(debug.getStringValue(-1)).to.be.undefined;
+      expect(debug.getStringValue(-1.1)).to.be.undefined;
+
+      expect(debug.getStringValue('abc')).to.be.a('string');
+      expect(debug.getStringValue(Buffer.from ? Buffer.from('abc') : new Buffer('abc'))).to.be.a('string');
+      expect(debug.getStringValue(new Date())).to.be.a('string');
+      expect(debug.getStringValue({ foo: { bar: 'qux' } })).to.be.a('string');
+    });
+  });
+
+  // describe('.exports.genRedactedString', function () {
+  //   it('should return a string, truncated if applicable', function () {
+  //     // TODO: the unit test underneath already tests the actual string truncation logic .
+  //     //       .. so this one is not needed?
+  //   });
+  // });
+
+  describe('.exports', function () {
+    it('should return a function', function () {
+      expect(debug('test')).to.be.a('function');
+    });
+
+    it('should output to console if DEBUG is set', function () {
+      var dbg_ns = 'ioredis:debugtest';
+
+      real_debug.enable(dbg_ns);
+
+      var logspy = spy();
+      var fn = debug(dbg_ns);
+
+      fn.log = logspy;
+
+      expect(fn.enabled).to.equal(true);
+      expect(fn.namespace).to.equal(dbg_ns);
+
+      var data = [], i = 0;
+
+      while (i < 1000) {
+        data.push(String(i)); i += 1;
+      }
+
+      var datastr = JSON.stringify(data);
+
+      fn('my message %s', { json: data });
+      expect(logspy.called).to.equal(true);
+
+      var args = logspy.getCall(0).args;
+
+      var wanted_arglen = 30 // " ... <REDACTED full-length="">"
+                        + debug.MAX_ARGUMENT_LENGTH // max-length of redacted string
+                        + datastr.length.toString().length; // length of string of string length (inception much?)
+
+      expect(args.length).to.be.above(1);
+      expect(args[1]).to.be.a('string');
+      expect(args[1].length).to.equal(wanted_arglen);
+    });
+  });
+});