Make logs better for users and fix flaky test (#33)

* fix: add a b58 formatter for logging and update logs

package.json

@@ -46,6 +46,7 @@
     "k-bucket": "^4.0.1",
     "libp2p-crypto": "~0.13.0",
     "libp2p-record": "~0.5.1",
+    "multihashes": "~0.4.14",
     "multihashing-async": "~0.5.1",
     "peer-id": "~0.11.0",
     "peer-info": "~0.14.1",
@@ -57,7 +58,7 @@
     "xor-distance": "^1.0.0"
   },
   "devDependencies": {
-    "aegir": "^15.0.0",
+    "aegir": "^15.1.0",
     "chai": "^4.1.2",
     "datastore-level": "~0.8.0",
     "dirty-chai": "^2.0.1",

src/index.js

@@ -154,7 +154,7 @@ class KadDHT {
    * @returns {void}
    */
   put (key, value, callback) {
-    this._log('PutValue %s', key)
+    this._log('PutValue %b', key)
     let sign
     try {
       sign = libp2pRecord.validator.isSigned(this.validators, key)
@@ -214,7 +214,7 @@ class KadDHT {
       maxTimeout = c.minute
     }
 
-    this._log('getMany %s (%s)', key, nvals)
+    this._log('getMany %b (%s)', key, nvals)
     const vals = []
 
     this._getLocal(key, (err, localRec) => {
@@ -294,7 +294,7 @@ class KadDHT {
    * @returns {void}
    */
   getClosestPeers (key, callback) {
-    this._log('getClosestPeers to %s', key.toString())
+    this._log('getClosestPeers to %b', key)
     utils.convertBuffer(key, (err, id) => {
       if (err) {
         return callback(err)

src/peer-queue.js

@@ -53,7 +53,7 @@ class PeerQueue {
    * @param {Buffer} from - The sha2-256 encoded peer id
    */
   constructor (from) {
-    log('create: %s', from.toString('hex'))
+    log('create: %b', from)
     this.from = from
     this.heap = new Heap(utils.xorCompare)
   }
@@ -66,7 +66,7 @@ class PeerQueue {
    * @returns {void}
    */
   enqueue (id, callback) {
-    log('enqueue %s', id.id.toString('hex'))
+    log('enqueue %s', id.toB58String())
     utils.convertPeerId(id, (err, key) => {
       if (err) {
         return callback(err)

src/private.js

@@ -91,7 +91,7 @@ module.exports = (dht) => ({
    *@private
    */
   _checkLocalDatastore (key, callback) {
-    dht._log('checkLocalDatastore: %s', key)
+    dht._log('checkLocalDatastore: %b', key)
     const dsKey = utils.bufferToKey(key)
 
     // 2. fetch value from ds
@@ -201,7 +201,7 @@ module.exports = (dht) => ({
    * @private
    */
   _closerPeersSingle (key, peer, callback) {
-    dht._log('_closerPeersSingle %s from %s', key, peer.toB58String())
+    dht._log('_closerPeersSingle %b from %s', key, peer.toB58String())
     dht._findPeerSingle(peer, new PeerId(key), (err, msg) => {
       if (err) {
         return callback(err)
@@ -290,14 +290,14 @@ module.exports = (dht) => ({
    * @private
    */
   _get (key, maxTimeout, callback) {
-    dht._log('_get %s', key.toString())
+    dht._log('_get %b', key)
     waterfall([
       (cb) => dht.getMany(key, 16, maxTimeout, cb),
       (vals, cb) => {
         const recs = vals.map((v) => v.val)
         const i = libp2pRecord.selection.bestRecord(dht.selectors, key, recs)
         const best = recs[i]
-        dht._log('GetValue %s %s', key.toString(), best)
+        dht._log('GetValue %b %s', key, best)
 
         if (!best) {
           return cb(new errors.NotFoundError())
@@ -345,12 +345,12 @@ module.exports = (dht) => ({
    * @private
    */
   _getLocal (key, callback) {
-    dht._log('getLocal %s', key)
+    dht._log('getLocal %b', key)
 
     waterfall([
       (cb) => dht.datastore.get(utils.bufferToKey(key), cb),
       (raw, cb) => {
-        dht._log('found %s in local datastore', key)
+        dht._log('found %b in local datastore', key)
         let rec
         try {
           rec = Record.deserialize(raw)

src/query.js

@@ -3,6 +3,7 @@
 const waterfall = require('async/waterfall')
 const each = require('async/each')
 const queue = require('async/queue')
+const mh = require('multihashes')
 
 const c = require('./constants')
 const PeerQueue = require('./peer-queue')
@@ -25,7 +26,7 @@ class Query {
     this.key = key
     this.query = query
     this.concurrency = c.ALPHA
-    this._log = utils.logger(this.dht.peerInfo.id, 'query:' + key.toString())
+    this._log = utils.logger(this.dht.peerInfo.id, 'query:' + mh.toB58String(key))
   }
 
   /**

src/rpc/handlers/get-value.js

@@ -20,7 +20,7 @@ module.exports = (dht) => {
   return function getValue (peer, msg, callback) {
     const key = msg.key
 
-    log('key: %s', key)
+    log('key: %b', key)
 
     if (!key || key.length === 0) {
       return callback(new Error('Invalid key'))

src/rpc/handlers/put-value.js

@@ -15,7 +15,7 @@ module.exports = (dht) => {
    */
   return function putValue (peer, msg, callback) {
     const key = msg.key
-    log('key: %s', key)
+    log('key: %b', key)
 
     const record = msg.record
 

src/utils.js

@@ -2,6 +2,7 @@
 
 const debug = require('debug')
 const multihashing = require('multihashing-async')
+const mh = require('multihashes')
 const Key = require('interface-datastore').Key
 const base32 = require('base32.js')
 const distance = require('xor-distance')
@@ -171,6 +172,12 @@ exports.logger = (id, subsystem) => {
   if (id) {
     name.push(`${id.toB58String().slice(0, 8)}`)
   }
+
+  // Add a formatter for converting to a base58 string
+  debug.formatters.b = (v) => {
+    return mh.toB58String(v)
+  }
+
   const logger = debug(name.join(':'))
   logger.error = debug(name.concat(['error']).join(':'))
 

test/providers.spec.js

@@ -116,7 +116,8 @@ describe('Providers', () => {
           providers.stop()
           done()
         })
-      }, 300)
+        // TODO: this is a timeout based check, make cleanup monitorable
+      }, 400)
     })
   })