chain: refactor event emission and logging.

lib/blockchain/chain.js

@@ -89,83 +89,10 @@ function Chain(options) {
   this.orphanSize = 0;
 
   this.db = new ChainDB(this);
-
-  this._init();
 }
 
 util.inherits(Chain, AsyncObject);
 
-/**
- * Initialize the chain.
- * @private
- */
-
-Chain.prototype._init = function _init() {
-  var self = this;
-
-  this.on('competitor', function(block, entry) {
-    self.logger.warning('Heads up: Competing chain at height %d:'
-      + ' tip-height=%d competitor-height=%d'
-      + ' tip-hash=%s competitor-hash=%s'
-      + ' tip-chainwork=%s competitor-chainwork=%s'
-      + ' chainwork-diff=%s',
-      entry.height,
-      self.tip.height,
-      entry.height,
-      self.tip.rhash(),
-      entry.rhash(),
-      self.tip.chainwork.toString(),
-      entry.chainwork.toString(),
-      self.tip.chainwork.sub(entry.chainwork).toString());
-  });
-
-  this.on('resolved', function(block, entry) {
-    self.logger.debug('Orphan %s (%d) was resolved.',
-      block.rhash(), entry.height);
-  });
-
-  this.on('checkpoint', function(hash, height) {
-    self.logger.debug('Hit checkpoint block %s (%d).',
-      util.revHex(hash), height);
-  });
-
-  this.on('fork', function(hash, height, expected) {
-    self.logger.warning(
-      'Fork at height %d: expected=%s received=%s',
-      height,
-      util.revHex(expected),
-      util.revHex(hash)
-    );
-  });
-
-  this.on('reorganize', function(block, height, expected) {
-    self.logger.warning(
-      'Reorg at height %d: old=%s new=%s',
-      height,
-      util.revHex(expected),
-      block.rhash()
-    );
-  });
-
-  this.on('invalid', function(block, height) {
-    self.logger.warning('Invalid block at height %d: hash=%s',
-      height, block.rhash());
-  });
-
-  this.on('exists', function(block, height) {
-    self.logger.debug('Already have block %s (%d).', block.rhash(), height);
-  });
-
-  this.on('orphan', function(block, height) {
-    self.logger.debug('Handled orphan %s (%d).', block.rhash(), height);
-  });
-
-  this.on('purge', function(count, size) {
-    self.logger.debug('Warning: %d (%dmb) orphans cleared!',
-      count, util.mb(size));
-  });
-};
-
 /**
  * Open the chain, wait for the database to load.
  * @method
@@ -270,13 +197,7 @@ Chain.prototype.verifyBlock = co(function* verifyBlock(block) {
  */
 
 Chain.prototype._verifyBlock = co(function* verifyBlock(block) {
-  var flags = common.flags.DEFAULT_FLAGS;
+  var flags = common.flags.DEFAULT_FLAGS & ~common.flags.VERIFY_POW;
-
-  if (block.prevBlock !== this.tip.hash)
-    throw new VerifyError(block, 'invalid', 'bad-prevblk', 0);
-
-  flags &= ~common.flags.VERIFY_POW;
-
   return yield this.verifyContext(block, this.tip, flags);
 });
 
@@ -310,6 +231,9 @@ Chain.prototype.verify = co(function* verify(block, prev, flags) {
 
   assert(typeof flags === 'number');
 
+  if (block.prevBlock !== prev.hash)
+    throw new VerifyError(block, 'invalid', 'bad-prevblk', 0);
+
   // Non-contextual checks.
   if (flags & common.flags.VERIFY_BODY) {
     if (!block.verifyBody(ret)) {
@@ -808,7 +732,15 @@ Chain.prototype.reorganize = co(function* reorganize(competitor, block) {
     yield this.reconnect(entry);
   }
 
-  this.emit('reorganize', block, tip.height, tip.hash);
+  this.logger.warning(
+    'Chain reorganization: old=%s(%d) new=%s(%d)',
+    tip.rhash(),
+    tip.height,
+    competitor.rhash(),
+    competitor.height
+  );
+
+  this.emit('reorganize', tip, competitor);
 });
 
 /**
@@ -852,7 +784,19 @@ Chain.prototype.reorganizeSPV = co(function* reorganizeSPV(competitor, block) {
     this.emit('disconnect', entry, headers, view);
   }
 
-  this.emit('reorganize', block, tip.height, tip.hash);
+  this.logger.warning(
+    'SPV reorganization: old=%s(%d) new=%s(%d)',
+    tip.rhash(),
+    tip.height,
+    competitor.rhash(),
+    competitor.height
+  );
+
+  this.logger.warning(
+    'Chain replay from height %d necessary.',
+    fork.height);
+
+  this.emit('reorganize', tip, competitor);
 });
 
 /**
@@ -915,7 +859,9 @@ Chain.prototype.reconnect = co(function* reconnect(entry) {
     if (err.type === 'VerifyError') {
       if (!err.malleated)
         this.setInvalid(entry.hash);
-      this.emit('invalid', block, entry.height);
+      this.logger.warning(
+        'Tried to reconnect invalid block: %s (%d).',
+        entry.rhash(), entry.height);
     }
     throw err;
   }
@@ -978,7 +924,9 @@ Chain.prototype.setBestChain = co(function* setBestChain(entry, block, prev, fla
     if (err.type === 'VerifyError') {
       if (!err.malleated)
         this.setInvalid(entry.hash);
-      this.emit('invalid', block, entry.height);
+      this.logger.warning(
+        'Tried to connect invalid block: %s (%d).',
+        entry.rhash(), entry.height);
     }
     throw err;
   }
@@ -1016,7 +964,9 @@ Chain.prototype.saveAlternate = co(function* saveAlternate(entry, block, prev, f
     if (err.type === 'VerifyError') {
       if (!err.malleated)
         this.setInvalid(entry.hash);
-      this.emit('invalid', block, entry.height);
+      this.logger.warning(
+        'Invalid block on alternate chain: %s (%d).',
+        entry.rhash(), entry.height);
     }
     throw err;
   }
@@ -1030,6 +980,20 @@ Chain.prototype.saveAlternate = co(function* saveAlternate(entry, block, prev, f
 
   yield this.db.save(entry, block);
 
+  this.logger.warning('Heads up: Competing chain at height %d:'
+    + ' tip-height=%d competitor-height=%d'
+    + ' tip-hash=%s competitor-hash=%s'
+    + ' tip-chainwork=%s competitor-chainwork=%s'
+    + ' chainwork-diff=%s',
+    entry.height,
+    this.tip.height,
+    entry.height,
+    this.tip.rhash(),
+    entry.rhash(),
+    this.tip.chainwork.toString(),
+    entry.chainwork.toString(),
+    this.tip.chainwork.sub(entry.chainwork).toString());
+
   // Emit as a "competitor" block.
   this.emit('competitor', block, entry);
 });
@@ -1208,7 +1172,8 @@ Chain.prototype.add = co(function* add(block, flags) {
 
 Chain.prototype._add = co(function* add(block, flags) {
   var initial = true;
-  var hash, entry, prev, result;
+  var result = null;
+  var hash, entry, prev;
 
   if (flags == null)
     flags = common.flags.DEFAULT_FLAGS;
@@ -1223,40 +1188,38 @@ Chain.prototype._add = co(function* add(block, flags) {
 
     // Special case for genesis block.
     if (hash === this.network.genesis.hash) {
-      this.emit('exists', block, block.getCoinbaseHeight());
+      this.logger.debug('Saw genesis block: %s.', block.rhash());
       throw new VerifyError(block, 'duplicate', 'duplicate', 0);
     }
 
     // Do we already have this block in the queue?
     if (this.hasPending(hash)) {
-      this.emit('exists', block, block.getCoinbaseHeight());
+      this.logger.debug('Already have pending block: %s.', block.rhash());
       throw new VerifyError(block, 'duplicate', 'duplicate', 0);
     }
 
     // If the block is already known to be
     // an orphan, ignore it.
-    if (this.seenOrphan(hash)) {
+    if (this.hasOrphan(hash)) {
-      this.emit('orphan', block, block.getCoinbaseHeight());
+      this.logger.debug('Already have orphan block: %s.', block.rhash());
       throw new VerifyError(block, 'duplicate', 'duplicate', 0);
     }
 
     // Do not revalidate known invalid blocks.
     if (this.hasInvalid(hash, block)) {
-      this.emit('invalid', block, block.getCoinbaseHeight());
+      this.logger.debug('Invalid ancestors for block: %s.', block.rhash());
       throw new VerifyError(block, 'duplicate', 'duplicate', 100);
     }
 
     // Check the POW before doing anything.
     if (flags & common.flags.VERIFY_POW) {
-      if (!block.verifyPOW()) {
+      if (!block.verifyPOW())
-        this.emit('invalid', block, block.getCoinbaseHeight());
         throw new VerifyError(block, 'invalid', 'high-hash', 50);
-      }
     }
 
     // Do we already have this block?
     if (yield this.db.hasEntry(hash)) {
-      this.emit('exists', block, block.getCoinbaseHeight());
+      this.logger.debug('Already have block: %s.', block.rhash());
       throw new VerifyError(block, 'duplicate', 'duplicate', 0);
     }
 
@@ -1266,6 +1229,8 @@ Chain.prototype._add = co(function* add(block, flags) {
     // If previous block wasn't ever seen,
     // add it current to orphans and break.
     if (!prev) {
+      assert(initial);
+      assert(!result);
       this.storeOrphan(block);
       throw new VerifyError(block, 'invalid', 'bad-prevblk', 0);
     }
@@ -1295,7 +1260,7 @@ Chain.prototype._add = co(function* add(block, flags) {
         throw new VerifyError(block,
           'malformed',
           'error parsing message',
-          100);
+          10);
       }
     }
 
@@ -1316,8 +1281,11 @@ Chain.prototype._add = co(function* add(block, flags) {
       // Attempt to add block to the chain index.
       yield this.setBestChain(entry, block, prev, flags);
 
-      if (!initial)
+      if (!initial) {
+        this.logger.debug('Orphan %s (%d) was resolved.',
+          block.rhash(), entry.height);
         this.emit('resolved', block, entry);
+      }
     }
 
     // Keep track of stats.
@@ -1425,6 +1393,8 @@ Chain.prototype.verifyCheckpoint = function verifyCheckpoint(prev, hash) {
     return true;
 
   if (hash === checkpoint) {
+    this.logger.debug('Hit checkpoint block %s (%d).',
+      util.revHex(hash), height);
     this.emit('checkpoint', hash, height);
     return true;
   }
@@ -1433,48 +1403,18 @@ Chain.prototype.verifyCheckpoint = function verifyCheckpoint(prev, hash) {
   // an old block for no reason, or the
   // consensus protocol is broken and
   // there was a 20k+ block reorg.
-  this.logger.warning('Checkpoint mismatch!');
+  this.logger.warning(
+    'Checkpoint mismatch at height %d: expected=%s received=%s',
+    height,
+    util.revHex(checkpoint),
+    util.revHex(hash)
+  );
 
   this.purgeOrphans();
 
-  this.emit('fork', hash, height, checkpoint);
-
   return false;
 };
 
-/**
- * Verify we do not already have an orphan.
- * Throw if there is an orphan fork.
- * @private
- * @param {Block} block
- * @returns {Boolean}
- * @throws {VerifyError}
- */
-
-Chain.prototype.seenOrphan = function seenOrphan(block) {
-  var orphan = this.orphanPrev[block.prevBlock];
-  var hash;
-
-  if (!orphan)
-    return false;
-
-  hash = block.hash('hex');
-
-  // The orphan chain forked.
-  if (orphan.hash('hex') !== hash) {
-    this.emit('fork', hash,
-      block.getCoinbaseHeight(),
-      orphan.hash('hex'));
-
-    this.resolveOrphan(block.prevBlock);
-    this.storeOrphan(block);
-
-    throw new VerifyError(block, 'invalid', 'bad-prevblk', 0);
-  }
-
-  return true;
-};
-
 /**
  * Store an orphan.
  * @private
@@ -1484,13 +1424,30 @@ Chain.prototype.seenOrphan = function seenOrphan(block) {
 Chain.prototype.storeOrphan = function storeOrphan(block) {
   var hash = block.hash('hex');
   var height = block.getCoinbaseHeight();
+  var orphan = this.orphanPrev[block.prevBlock];
+
+  // The orphan chain forked.
+  if (orphan) {
+    assert(orphan.hash('hex') !== hash);
+    assert(orphan.prevBlock === block.prevBlock);
+
+    this.logger.warning(
+      'Removing forked orphan block: %s (%d).',
+      orphan.rhash(), height);
+
+    this.resolveOrphan(block.prevBlock);
+  }
 
   this.orphanCount++;
   this.orphanSize += block.getSize();
   this.orphanPrev[block.prevBlock] = block;
   this.orphanMap[hash] = block;
 
-  this.emit('orphan', block, height);
+  this.logger.debug(
+    'Storing orphan block: %s (%d).',
+    block.rhash(), height);
+
+  this.emit('orphan', block);
 };
 
 /**
@@ -1531,7 +1488,8 @@ Chain.prototype.purgeOrphans = function purgeOrphans() {
   this.orphanCount = 0;
   this.orphanSize = 0;
 
-  this.emit('purge', count, size);
+  this.logger.debug('Purged %d orphans (%dmb).',
+    count, util.mb(size));
 };
 
 /**
@@ -1540,11 +1498,15 @@ Chain.prototype.purgeOrphans = function purgeOrphans() {
  */
 
 Chain.prototype.pruneOrphans = function pruneOrphans() {
-  var i, hashes, hash, orphan, height, best, last;
+  var i, hashes, hash, orphan, height;
+  var bestOrphan, bestHeight, lastOrphan;
 
   if (this.orphanSize <= this.options.orphanLimit)
     return false;
 
+  this.logger.warning('Pruning %d (%dmb) orphans!',
+    this.orphanCount, util.mb(this.orphanSize));
+
   hashes = Object.keys(this.orphanPrev);
 
   if (hashes.length === 0)
@@ -1557,16 +1519,18 @@ Chain.prototype.pruneOrphans = function pruneOrphans() {
 
     delete this.orphanPrev[hash];
 
-    if (!best || height > best.getCoinbaseHeight())
+    if (!bestOrphan || height > bestHeight) {
-      best = orphan;
+      bestOrphan = orphan;
+      bestHeight = height;
+    }
 
-    last = orphan;
+    lastOrphan = orphan;
   }
 
   // Save the best for last... or the
   // last for best in this case.
-  if (best.getCoinbaseHeight() <= 0)
+  if (bestHeight === -1)
-    best = last;
+    bestOrphan = lastOrphan;
 
   hashes = Object.keys(this.orphanMap);
 
@@ -1576,18 +1540,14 @@ Chain.prototype.pruneOrphans = function pruneOrphans() {
 
     delete this.orphanMap[hash];
 
-    if (orphan !== best)
+    if (orphan !== bestOrphan)
       this.emit('unresolved', orphan);
   }
 
-  this.emit('purge',
+  this.orphanPrev[bestOrphan.prevBlock] = bestOrphan;
-    this.orphanCount - 1,
+  this.orphanMap[bestOrphan.hash('hex')] = bestOrphan;
-    this.orphanSize - best.getSize());
-
-  this.orphanPrev[best.prevBlock] = best;
-  this.orphanMap[best.hash('hex')] = best;
   this.orphanCount = 1;
-  this.orphanSize = best.getSize();
+  this.orphanSize = bestOrphan.getSize();
 
   return true;
 };