feat: truncate large/long debug output arguments (#523)

* wrap the debug node_module so that debug output args are always truncated (avoids potentially MBs of data being outout to console)

* make calling the wrapped debug instance (more or less) a no-op if debug.enabled is currently FALSE

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 = {};

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');

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) {

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');

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');

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');
 

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/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);
+    });
+  });
+});