logger: make logs less spammy.

lib/bcoin/fees.js

@@ -246,7 +246,7 @@ ConfirmStats.prototype.addTX = function addTX(height, val) {
   var bucketIndex = this.bucketMap.search(val);
   var blockIndex = height % this.unconfTX.length;
   this.unconfTX[blockIndex][bucketIndex]++;
-  this.logger.debug('estimatefee: Adding tx to %s.', this.type);
+  this.logger.spam('estimatefee: Adding tx to %s.', this.type);
   return bucketIndex;
 };
 
@@ -454,7 +454,7 @@ PolicyEstimator.prototype.removeTX = function removeTX(hash) {
   var item = this.map[hash];
 
   if (!item) {
-    this.logger.debug(
+    this.logger.spam(
       'estimatefee: Mempool tx %s not found.',
       utils.revHex(hash));
     return;
@@ -528,7 +528,7 @@ PolicyEstimator.prototype.processTX = function processTX(entry, current) {
   rate = entry.getRate();
   priority = entry.getPriority(height);
 
-  this.logger.debug('estimatefee: Processing mempool tx %s.', entry.tx.rhash);
+  this.logger.spam('estimatefee: Processing mempool tx %s.', entry.tx.rhash);
 
   if (fee === 0 || this.isPriPoint(rate, priority)) {
     this.map[hash] = {
@@ -542,9 +542,8 @@ PolicyEstimator.prototype.processTX = function processTX(entry, current) {
       bucketIndex: this.feeStats.addTX(height, rate)
     };
     this.mapSize++;
-    this.logger.debug('estimatefee: Rate: %d.', this.estimateFee());
   } else {
-    this.logger.debug('estimatefee: Not adding tx %s.', entry.tx.rhash);
+    this.logger.spam('estimatefee: Not adding tx %s.', entry.tx.rhash);
   }
 };
 
@@ -646,6 +645,8 @@ PolicyEstimator.prototype.processBlock = function processBlock(height, entries,
   this.logger.debug('estimatefee: Done updating estimates'
     + ' for %d confirmed entries. New mempool map size %d.',
     entries.length, this.mapSize);
+
+  this.logger.debug('estimatefee: Rate: %d.', this.estimateFee());
 };
 
 /**

lib/bcoin/logger.js

@@ -59,7 +59,8 @@ Logger.levels = {
   error: 1,
   warning: 2,
   info: 3,
-  debug: 4
+  debug: 4,
+  spam: 5
 };
 
 /**
@@ -71,7 +72,8 @@ Logger.colors = {
   error: '1;31',
   warning: '1;33',
   info: '94',
-  debug: '90'
+  debug: '90',
+  spam: '90'
 };
 
 /**
@@ -195,6 +197,26 @@ Logger.prototype.debug = function debug() {
   this.log('debug', args);
 };
 
+/**
+ * Output a log to the `spam` log level.
+ * @param {String|Object} obj
+ * @param {...Object} args
+ */
+
+Logger.prototype.spam = function spam() {
+  var i, args;
+
+  if (this.level < Logger.levels.spam)
+    return;
+
+  args = new Array(arguments.length);
+
+  for (i = 0; i < args.length; i++)
+    args[i] = arguments[i];
+
+  this.log('spam', args);
+};
+
 /**
  * Output a log to the desired log level.
  * Note that this bypasses the level check.

lib/bcoin/mempool.js

@@ -374,7 +374,7 @@ Mempool.prototype.limitOrphans = function limitOrphans() {
     hash = orphans[i];
     orphans.splice(i, 1);
 
-    this.logger.debug('Removing orphan %s from mempool.', utils.revHex(hash));
+    this.logger.spam('Removing orphan %s from mempool.', utils.revHex(hash));
 
     this.removeOrphan(hash);
   }
@@ -859,7 +859,7 @@ Mempool.prototype.addUnchecked = function addUnchecked(entry, callback, force) {
             self.emit('error', err);
             return next();
           }
-          self.logger.debug('Resolved orphan %s in mempool.', entry.tx.rhash);
+          self.logger.spam('Resolved orphan %s in mempool.', entry.tx.rhash);
           next();
         }, true);
       });

lib/bcoin/peer.js

@@ -448,7 +448,7 @@ Peer.prototype.sendInv = function sendInv(items) {
   if (items.length === 0)
     return;
 
-  this.logger.debug('Serving %d inv items to %s.',
+  this.logger.spam('Serving %d inv items to %s.',
     items.length, this.hostname);
 
   for (i = 0; i < items.length; i += 50000) {
@@ -477,7 +477,7 @@ Peer.prototype.sendHeaders = function sendHeaders(items) {
   if (items.length === 0)
     return;
 
-  this.logger.debug('Serving %d headers to %s.',
+  this.logger.spam('Serving %d headers to %s.',
     items.length, this.hostname);
 
   for (i = 0; i < items.length; i += 2000) {
@@ -1607,7 +1607,7 @@ Peer.prototype._handleAddr = function _handleAddr(addrs) {
   for (i = 0; i < addrs.length; i++)
     this.addrFilter.add(addrs[i].host, 'ascii');
 
-  this.logger.debug(
+  this.logger.info(
     'Received %d addrs (hosts=%d, peers=%d) (%s).',
     addrs.length,
     this.pool.hosts.length,
@@ -1750,7 +1750,7 @@ Peer.prototype._handleInv = function _handleInv(items) {
     this.emit('txs', txs);
 
   if (unknown != null) {
-    this.logger.debug(
+    this.logger.warning(
       'Peer sent an unknown inv type: %d (%s).',
       unknown, this.hostname);
   }
@@ -1945,7 +1945,7 @@ Peer.prototype._handleGetBlockTxn = function _handleGetBlockTxn(req) {
       return done(err);
 
     if (!block) {
-      self.logger.info(
+      self.logger.debug(
         'Peer sent getblocktxn for non-existent block (%s).',
         self.hostname);
       self.setMisbehavior(100);
@@ -1953,7 +1953,7 @@ Peer.prototype._handleGetBlockTxn = function _handleGetBlockTxn(req) {
     }
 
     if (block.height < self.chain.tip.height - 15) {
-      self.logger.info(
+      self.logger.debug(
         'Peer sent a getblocktxn for a block > 15 deep (%s)',
         self.hostname);
       return done();
@@ -1977,7 +1977,7 @@ Peer.prototype._handleBlockTxn = function _handleBlockTxn(res) {
   var block = this.compactBlocks[res.hash];
 
   if (!block) {
-    this.logger.info('Peer sent unsolicited blocktxn (%s).', this.hostname);
+    this.logger.debug('Peer sent unsolicited blocktxn (%s).', this.hostname);
     return;
   }
 
@@ -1988,7 +1988,7 @@ Peer.prototype._handleBlockTxn = function _handleBlockTxn(res) {
 
   if (!block.fillMissing(res)) {
     this.setMisbehavior(100);
-    this.logger.info('Peer sent non-full blocktxn (%s).', this.hostname);
+    this.logger.warning('Peer sent non-full blocktxn (%s).', this.hostname);
     return;
   }
 

lib/bcoin/pool.js

@@ -896,14 +896,15 @@ Pool.prototype._handleBlock = function _handleBlock(block, peer, callback) {
 
     self.emit('chain-progress', self.chain.getProgress(), peer);
 
-    if (self.logger.level === 4 && self.chain.total % 20 === 0) {
+    if (self.logger.level >= 4 && self.chain.total % 20 === 0) {
       self.logger.debug('Status:'
-        + ' ts=%s height=%d progress=%s'
+        + ' ts=%s height=%d highest=%d progress=%s'
         + ' blocks=%d orphans=%d active=%d'
         + ' queue=%d target=%s peers=%d'
-        + ' pending=%d highest=%d jobs=%d',
+        + ' pending=%d jobs=%d',
         utils.date(block.ts),
         self.chain.height,
+        self.chain.bestHeight,
         (self.chain.getProgress() * 100).toFixed(2) + '%',
         self.chain.total,
         self.chain.orphan.count,
@@ -912,7 +913,6 @@ Pool.prototype._handleBlock = function _handleBlock(block, peer, callback) {
         block.bits,
         self.peers.all.length,
         self.chain.locker.pending.length,
-        self.chain.bestHeight,
         self.chain.locker.jobs.length);
     }