Add debug output (hypercore-protocol#6)

* add debugMode option

* rewrite debug output to use the debug module

Author: pfrazee

index.js

@@ -11,6 +11,7 @@ var equals = require('buffer-equals')
 var varint = require('varint')
 var xtend = require('xtend')
 var pe = require('passthrough-encoding')
+var debug = require('debug')('hypercore-protocol')
 var messages = require('./messages')
 
 var KEEP_ALIVE = Buffer([0])
@@ -118,6 +119,7 @@ function use (extensions) {
   }
 
   Channel.prototype._onhandshake = function (handshake) {
+    niceDebug('handshaked', { channel: this })
     this.protocol._onhandshake(handshake)
   }
 
@@ -194,6 +196,7 @@ function use (extensions) {
 
       var keys = Object.keys(self.channels)
       for (var i = 0; i < keys.length; i++) {
+        niceDebug('closed', { channel: self.channels[keys[i]] })
         self._close(self.channels[keys[i]])
       }
     }
@@ -256,7 +259,10 @@ function use (extensions) {
   }
 
   Protocol.prototype.open = function (key, opts) {
-    if (this.destroyed) return null // already finalized
+    if (this.destroyed) {
+      niceDebug('Open() called after finalized, aborting', { key: key })
+      return null // already finalized
+    }
     if (!opts) opts = {}
 
     var d = opts.discoveryKey || discoveryKey(key)
@@ -277,6 +283,7 @@ function use (extensions) {
     ch.local = this._local.indexOf(null)
     if (ch.local === -1) ch.local = this._local.push(null) - 1
     this._local[ch.local] = ch
+    niceDebug('open()', { channel: ch })
 
     var open = messages.Open.encode({
       feed: ch.discoveryKey,
@@ -302,7 +309,11 @@ function use (extensions) {
   }
 
   Protocol.prototype._send = function (channel, type, message) {
-    if (channel.closed) return false
+    if (channel.closed) {
+      niceDebug('Send called after close, discarding', { channel: channel, type: type, message: message })
+      return false
+    }
+    niceDebug('send()', { channel: channel, type: type, message: message })
 
     var enc = types[type]
     var len = enc ? enc.encodingLength(message) : 0
@@ -335,10 +346,12 @@ function use (extensions) {
   }
 
   Protocol.prototype._pause = function () {
+    debug('pause()')
     if (!this._paused++) this._decode.pause()
   }
 
   Protocol.prototype._resume = function () {
+    debug('resume()')
     if (!--this._paused) this._decode.resume()
   }
 
@@ -362,7 +375,11 @@ function use (extensions) {
   Protocol.prototype._parse = function (data) {
     this._remoteKeepAlive = 0
 
-    if (!data.length || this.destroyed) return
+    if (!data.length) return
+    if (this.destroyed) {
+      debug('Received message after destroy(), discarding')
+      return
+    }
 
     var remote = varint.decode(data, 0)
     var offset = varint.decode.bytes
@@ -410,7 +427,11 @@ function use (extensions) {
       this.channels[keyHex] = ch
     }
 
-    if (ch.remote > -1) return this.destroy(new Error('Double open for same channel'))
+    if (ch.remote > -1) {
+      debug('Double open error, closing channel', { channel: ch, message: open })
+      return this.destroy(new Error('Double open for same channel'))
+    }
+    niceDebug('opened', { channel: ch, message: open })
 
     ch.remote = remote
     ch._remoteNonce = open.nonce
@@ -424,19 +445,34 @@ function use (extensions) {
     var channel = this._remote[remote]
 
     if (!channel.key || channel.buffer.length || !channel._ready) {
-      if (channel.buffer.length === 16) return this.destroy(new Error('Buffer overflow'))
+      if (channel.buffer.length === 16) {
+        niceDebug('Buffer overflow in received message, closing channel', { channel: channel })
+        return this.destroy(new Error('Buffer overflow'))
+      }
       channel.buffer.push(data)
       return
     }
 
     var box = this._decrypt(channel, data.slice(offset))
-    if (!box || !box.length) return this.destroy(new Error('Invalid message'))
+    if (!box || !box.length) {
+      niceDebug('Received invalid message, closing channel', { channel: channel })
+      return this.destroy(new Error('Invalid message'))
+    }
 
     var type = this._parseType(box[0])
-    if (type < 0) return
+    if (type < 0) {
+      niceDebug('Received invalid message type, discarding', { channel: channel, type: type })
+      return
+    }
 
-    if (type && !this.remoteId) return this.destroy(new Error('Did not receive handshake'))
-    if (type >= types.length) return
+    if (type && !this.remoteId) {
+      niceDebug('Received message without handshake, destroying channel', { channel: channel })
+      return this.destroy(new Error('Did not receive handshake'))
+    }
+    if (type >= types.length) {
+      niceDebug('Received invalid message type, discarding', { channel: channel, type: type })
+      return
+    }
 
     var enc = types[type]
 
@@ -446,11 +482,13 @@ function use (extensions) {
       return this.destroy(err)
     }
 
+    niceDebug('recv()', { channel: channel, type: type, message: message })
     channel.emit(eventNames[type], message)
   }
 
   Protocol.prototype._onclose = function (remote) {
     var channel = this._remote[remote]
+    niceDebug('closed by remote', { channel: channel })
 
     this._remote[remote] = null
     channel.remote = -1
@@ -535,5 +573,28 @@ function use (extensions) {
 
   function noop () {}
 
+  function niceDebug (label, data) {
+    if (!debug.enabled) return
+    if (data) {
+      var parts = []
+      if (data.channel) parts.push('chan=' + shortHex(data.channel.discoveryKey))
+      parts.push(label)
+      if ('type' in data) {
+        var type = (types[data.type] && types[data.type].name) ? types[data.type].name : data.type
+        if (type === 6) type = 'Pause'
+        if (type === 7) type = 'Resume'
+        parts.push('type=' + type)
+      }
+      if (data.key) parts.push('key=' + shortHex(data.key))
+      debug(parts.join(' '))
+    } else {
+      debug(label)
+    }
+  }
+  function shortHex (buf) {
+    buf = buf.toString('hex')
+    return buf.slice(0, 6) + '..' + buf.slice(-2)
+  }
+
   return Protocol
 }

package.json

@@ -7,6 +7,7 @@
     "brfs": "^1.4.3",
     "buffer-equals": "^1.0.3",
     "create-hmac": "^1.1.4",
+    "debug": "^2.3.2",
     "duplexify": "^3.4.3",
     "increment-buffer": "^1.0.0",
     "inherits": "^2.0.1",

test.js

@@ -5,10 +5,12 @@ var lpm = require('length-prefixed-message')
 var key = Buffer('12345678123456781234567812345678')
 var otherKey = Buffer('02345678123456781234567812345678')
 
+var DEBUG_MODE = process.env.DEBUG_MODE ? 'log' : false
+
 tape('parse discovery key', function (t) {
   t.plan(1)
 
-  var stream = protocol()
+  var stream = protocol({ debugMode: DEBUG_MODE })
   var channel = stream.open(key)
   lpm.read(stream, function (buf) {
     var parsed = protocol.parseDiscoveryKey(buf)
@@ -19,8 +21,8 @@ tape('parse discovery key', function (t) {
 tape('open channel', function (t) {
   t.plan(3)
 
-  var stream1 = protocol()
-  var stream2 = protocol()
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE })
 
   var channel1 = stream1.open(key)
   var channel2 = stream2.open(key)
@@ -45,8 +47,8 @@ tape('open channel', function (t) {
 tape('async open', function (t) {
   t.plan(3)
 
-  var stream1 = protocol()
-  var stream2 = protocol(function () {
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE }, function () {
     setTimeout(function () {
       var channel2 = stream2.open(key)
       channel2.once('request', function (message) {
@@ -73,8 +75,8 @@ tape('async open', function (t) {
 tape('empty messages work', function (t) {
   t.plan(2)
 
-  var stream1 = protocol()
-  var stream2 = protocol()
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE })
 
   var channel1 = stream1.open(key)
   var channel2 = stream2.open(key)
@@ -94,8 +96,8 @@ tape('empty messages work', function (t) {
 })
 
 tape('is encrypted', function (t) {
-  var stream1 = protocol()
-  var stream2 = protocol()
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE })
 
   var channel1 = stream1.open(key)
   var channel2 = stream2.open(key)
@@ -116,8 +118,8 @@ tape('is encrypted', function (t) {
 })
 
 tape('can disable encryption', function (t) {
-  var stream1 = protocol({encrypt: false})
-  var stream2 = protocol({encrypt: false})
+  var stream1 = protocol({debugMode: DEBUG_MODE, encrypt: false})
+  var stream2 = protocol({debugMode: DEBUG_MODE, encrypt: false})
 
   var foundHello = false
   var channel1 = stream1.open(key)
@@ -142,8 +144,8 @@ tape('can disable encryption', function (t) {
 tape('end channel', function (t) {
   t.plan(3)
 
-  var stream1 = protocol()
-  var stream2 = protocol()
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE })
 
   var c1 = stream1.open(key)
   var c2 = stream2.open(key)
@@ -171,8 +173,8 @@ tape('end channel', function (t) {
 tape('destroy ends all channels', function (t) {
   t.plan(3)
 
-  var stream1 = protocol()
-  var stream2 = protocol()
+  var stream1 = protocol({ debugMode: DEBUG_MODE })
+  var stream2 = protocol({ debugMode: DEBUG_MODE })
 
   var c1 = stream1.open(key)
   var other = stream1.open(otherKey)
@@ -198,8 +200,8 @@ tape('destroy ends all channels', function (t) {
 })
 
 tape('times out', function (t) {
-  var p1 = protocol()
-  var p2 = protocol()
+  var p1 = protocol({ debugMode: DEBUG_MODE })
+  var p2 = protocol({ debugMode: DEBUG_MODE })
 
   // dummy timeout to keep event loop running
   var timeout = setTimeout(function () {}, 100000)
@@ -216,8 +218,8 @@ tape('times out', function (t) {
 })
 
 tape('timeout is implicit keep alive', function (t) {
-  var p1 = protocol()
-  var p2 = protocol()
+  var p1 = protocol({ debugMode: DEBUG_MODE })
+  var p2 = protocol({ debugMode: DEBUG_MODE })
 
   // dummy timeout to keep event loop running
   setTimeout(function () {
@@ -239,8 +241,8 @@ tape('timeout is implicit keep alive', function (t) {
 })
 
 tape('different timeouts', function (t) {
-  var p1 = protocol()
-  var p2 = protocol()
+  var p1 = protocol({ debugMode: DEBUG_MODE })
+  var p2 = protocol({ debugMode: DEBUG_MODE })
 
   // dummy timeout to keep event loop running
   var timeout = setTimeout(function () {}, 100000)
@@ -299,8 +301,8 @@ tape('different extensions', function (t) {
 
   var protocol1 = protocol.use({test: 1, bar: 1})
   var protocol2 = protocol.use({foo: 1, test: 1})
-  var p1 = protocol1()
-  var p2 = protocol2()
+  var p1 = protocol1({ debugMode: DEBUG_MODE })
+  var p2 = protocol2({ debugMode: DEBUG_MODE })
 
   var ch1 = p1.open(key)
   var ch2 = p2.open(key)
@@ -337,8 +339,8 @@ tape('ignore unsupported message', function (t) {
   t.plan(6)
 
   var protocol2 = protocol.use({test: 1, bar: 1})
-  var p1 = protocol()
-  var p2 = protocol2()
+  var p1 = protocol({ debugMode: DEBUG_MODE })
+  var p2 = protocol2({ debugMode: DEBUG_MODE })
 
   var ch1 = p1.open(key)
   var ch2 = p2.open(key)