From b265877b36a1e584dbed8880849242fa45e962d2 Mon Sep 17 00:00:00 2001 From: Christopher Jeffrey Date: Sat, 4 Mar 2017 15:34:16 -0800 Subject: [PATCH] chain: refactor event emission and logging. --- lib/blockchain/chain.js | 258 +++++++++++++++++----------------------- 1 file changed, 109 insertions(+), 149 deletions(-) diff --git a/lib/blockchain/chain.js b/lib/blockchain/chain.js index 8d49901f..be1f01e9 100644 --- a/lib/blockchain/chain.js +++ b/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; - - if (block.prevBlock !== this.tip.hash) - throw new VerifyError(block, 'invalid', 'bad-prevblk', 0); - - flags &= ~common.flags.VERIFY_POW; - + var flags = common.flags.DEFAULT_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)) { - this.emit('orphan', block, block.getCoinbaseHeight()); + if (this.hasOrphan(hash)) { + 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()) { - this.emit('invalid', block, block.getCoinbaseHeight()); + if (!block.verifyPOW()) 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()) - best = orphan; + if (!bestOrphan || height > bestHeight) { + 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) - best = last; + if (bestHeight === -1) + 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.orphanCount - 1, - this.orphanSize - best.getSize()); - - this.orphanPrev[best.prevBlock] = best; - this.orphanMap[best.hash('hex')] = best; + this.orphanPrev[bestOrphan.prevBlock] = bestOrphan; + this.orphanMap[bestOrphan.hash('hex')] = bestOrphan; this.orphanCount = 1; - this.orphanSize = best.getSize(); + this.orphanSize = bestOrphan.getSize(); return true; };