Fixed logging issues.

lib/services/block/index.js

@@ -149,6 +149,9 @@ BlockService.prototype.getRawBlock = function(hash, callback) {
     if(err) {
       return callback(err);
     }
+    if (!block) {
+      return callback();
+    }
     callback(null, block.toRaw().toString('hex'));
   });
 };
@@ -189,7 +192,6 @@ BlockService.prototype._checkTip = function(callback) {
       return callback();
     }
 
-    self._reorging = true;
     self._findCommonAncestor(function(err, commonAncestorHeader) {
       if(err) {
         return callback(err);
@@ -365,6 +367,14 @@ BlockService.prototype.start = function(callback) {
         return callback();
       }
 
+      self._header.on('reorg', function() {
+        self._reorging = true;
+      });
+
+      self._header.on('reorg complete', function() {
+        self._reorging = false;
+      });
+
       self._setTip(tip, callback);
     });
 
@@ -376,25 +386,34 @@ BlockService.prototype.stop = function(callback) {
   setImmediate(callback);
 };
 
+BlockService.prototype._getTimeSinceLastBlock = function(blockHash, prevBlockHash, callback) {
+
+  var self = this;
+
+  async.map([ blockHash, prevBlockHash ], function(hash, next) {
+    self._timestamp.getTimestamp(hash, next);
+  }, function(err, times) {
+    if (err) {
+      return callback(err);
+    }
+    return callback(null, utils.convertMillisecondsToHumanReadable((times[0] * 1000) - (times[1] * 1000)));
+  });
+
+};
+
 BlockService.prototype._queueBlock = function(block) {
 
   var self = this;
 
   self._blocksInQueue++;
+
   self._blockProcessor.push(block, function(err) {
 
     if (err) {
       return self._handleError(err);
     }
 
-    log.info('Block Service: The best block hash is: ' + self._tip.hash +
-      ' at height: ' + self._tip.height + ' Time since last block: ' +
-        utils.convertMillisecondsToHumanReadable(Date.now() - self._timeOfLastBlockReport));
-    self._timeOfLastBlockReport = Date.now();
-
-    log.debug('Block Service: completed processing block: ' + block.rhash() +
-      ' prev hash: ' + bcoin.util.revHex(block.prevBlock) + ' height: ' + self._tip.height);
-
+    self._logSynced(block.rhash());
     self._blocksInQueue--;
 
   });
@@ -693,6 +712,11 @@ BlockService.prototype._getReorgBlock = function(tip, callback) {
 BlockService.prototype._onBlock = function(block, callback) {
 
   var self = this;
+
+  if (self._reorging) {
+    return callback();
+  }
+
   self._getBlock(block.rhash(), function(err, _block) {
 
     if(err) {
@@ -813,6 +837,51 @@ BlockService.prototype._setTip = function(tip, callback) {
   this._saveTip(tip, callback);
 };
 
+BlockService.prototype._logSynced = function(blockHash) {
+
+  var self = this;
+
+  if (self._reorging) {
+    return;
+  }
+
+  var blockHeight;
+  var timeDiff;
+
+  async.waterfall([
+    function(next) {
+      self._header.getBlockHeader(blockHash, function(err, header) {
+        if (err) {
+          return next(err);
+        }
+        blockHeight = header.height;
+        next(null, header.prevHash);
+      });
+    },
+    function(prevBlockHash, next) {
+      self._getTimeSinceLastBlock(blockHash, prevBlockHash, function(err, diff) {
+
+        if (err) {
+          return self._handleError(err);
+        }
+
+        timeDiff = diff;
+        next();
+      });
+    }
+  ], function(err) {
+
+    if (err) {
+      return self._handleError(err);
+    }
+
+    log.info('Block Service: The best block hash is: ' + blockHash +
+      ' at height: ' + blockHeight + '. Time between the last 2 blocks (adjusted): ' + timeDiff);
+
+  });
+
+};
+
 BlockService.prototype._onSynced = function() {
   var self = this;
 
@@ -823,8 +892,7 @@ BlockService.prototype._onSynced = function() {
   self._logProgress();
   self._initialSync = false;
   self._startBlockSubscription();
-  log.info('Block Service: The best block hash is: ' + self._tip.hash +
-    ' at height: ' + self._tip.height);
+  self._logSynced(self._tip.hash);
 };
 
 BlockService.prototype._startSync = function() {

lib/services/header/index.js

@@ -28,6 +28,7 @@ var HeaderService = function(options) {
   this.GENESIS_HASH = constants.BITCOIN_GENESIS_HASH[this.node.network];
   this._lastHeader = null;
   this._initialSync = true;
+  this._originalHeight = 0;
 
   this._slowMode = options.slowMode;
 };
@@ -126,6 +127,8 @@ HeaderService.prototype.getBestHeight = function() {
 
 HeaderService.prototype._adjustTipBackToCheckpoint = function() {
 
+  this._originalHeight = this._tip.height;
+
   if (this._checkpoint === -1 || this._tip.height < this._checkpoint) {
 
     this._tip.height = 0;
@@ -300,6 +303,7 @@ HeaderService.prototype._persistHeader = function(block, callback) {
   }
 
   self._reorging =  true;
+  self.emit('reorg');
 
   self._handleReorg(block, function(err) {
 
@@ -507,7 +511,17 @@ HeaderService.prototype._onHeadersSave = function(callback) {
       return service.onHeaders.call(service, next);
     }
     next();
-  }, callback);
+  }, function(err) {
+
+    if (err) {
+      return callback(err);
+    }
+
+    self.emit('reorg complete');
+    self._reorging = false;
+    callback();
+
+  });
 
 };
 
@@ -603,6 +617,7 @@ HeaderService.prototype._handleReorg = function(block, callback) {
   // then, we'll get the last header from the database which will nuke out all the
   // headers that are greater than new tip height.
   self._adjustHeadersForCheckPointTip(function(err) {
+
     if(err) {
       return callback(err);
     }
@@ -611,7 +626,6 @@ HeaderService.prototype._handleReorg = function(block, callback) {
     // it can check to ensure the final set of header contains the reorg block.
     // in other words, our peer has completed its own reorg process and is delievering
     // us a valid set of headers.
-    self._reorgBlock = block;
     callback();
   });
 
@@ -650,7 +664,7 @@ HeaderService.prototype._startSync = function() {
   }, function() {
 
     self._reorging = false;
-    var numNeeded = self._bestHeight - self._tip.height;
+    var numNeeded = Math.max(self._bestHeight, self._originalHeight) - self._tip.height;
 
     // common case
     if (numNeeded > 0) {
@@ -961,6 +975,7 @@ HeaderService.prototype._adjustHeadersForCheckPointTip = function(callback) {
 
     assert(self._lastHeader, 'The last synced header was not in the database.');
     self._tip.hash = self._lastHeader.hash;
+    self._tip.height = self._lastHeader.height;
     self._db.batch(removalOps, callback);
 
   });

lib/services/timestamp/index.js

@@ -158,7 +158,6 @@ TimestampService.prototype.getTimestampSync = function(hash) {
 };
 
 TimestampService.prototype.getTimestamp = function(hash, callback) {
-
   var self = this;
 
   self._db.get(self._encoding.encodeBlockTimestampKey(hash), function(err, data) {

lib/services/transaction/index.js

@@ -269,6 +269,8 @@ TransactionService.prototype.onBlock = function(block, callback) {
       return callback(err);
     }
 
+    assert(block.txs.length === operations.length, 'It seems we are not indexing the correct number of transactions.');
+
     callback(null, operations);
   });