Merge pull request #440 from MaciejBaj/290-genesis-loading-progress

Add genesis block loading progress logger - Closes #290

modules/blocks.js

@@ -339,6 +339,7 @@ __private.applyGenesisBlock = function (block, cb) {
 			return 0;
 		}
 	});
+	var tracker = self.getBlockProgressLogger(block.transactions.length, block.transactions.length / 100, 'Genesis block loading');
 	async.eachSeries(block.transactions, function (transaction, cb) {
 		modules.accounts.setAccountAndGet({publicKey: transaction.senderPublicKey}, function (err, sender) {
 			if (err) {
@@ -349,6 +350,7 @@ __private.applyGenesisBlock = function (block, cb) {
 				});
 			}
 			__private.applyTransaction(block, transaction, sender, cb);
+			tracker.applyNext();
 		});
 	}, function (err) {
 		if (err) {
@@ -1332,7 +1334,7 @@ Blocks.prototype.onReceiveBlock = function (block) {
 				library.logger.info('Last block stands');
 				return setImmediate(cb);
 			} else {
-				// In other cases - we have wrong parent and should rewind. 
+				// In other cases - we have wrong parent and should rewind.
 				library.logger.info('Last block and parent loses');
 				async.series([
 					self.deleteLastBlock,
@@ -1398,13 +1400,13 @@ Blocks.prototype.aggregateBlocksReward = function (filter, cb) {
 
 	params.generatorPublicKey = filter.generatorPublicKey;
 	params.delegates = constants.activeDelegates;
-	
+
 	if (filter.start !== undefined) {
 		params.start = filter.start - constants.epochTime.getTime () / 1000;
 	}
-	
+
 	if (filter.end !== undefined) {
-		params.end = filter.end - constants.epochTime.getTime () / 1000; 
+		params.end = filter.end - constants.epochTime.getTime () / 1000;
 	}
 
 	library.db.query(sql.aggregateBlocksReward(params), params).then(function (rows) {
@@ -1420,6 +1422,52 @@ Blocks.prototype.aggregateBlocksReward = function (filter, cb) {
 	});
 };
 
+/**
+ * Creates logger for tracking applied transactions of block
+ *
+ * @param {Number} transactionsCount
+ * @param {Number} logsFrequency
+ * @param {String} msg
+ * @return {BlockProgressLogger}
+ */
+Blocks.prototype.getBlockProgressLogger = function (transactionsCount, logsFrequency, msg) {
+	function BlockProgressLogger (transactionsCount, logsFrequency, msg) {
+		this.target = transactionsCount;
+		this.step = Math.floor(transactionsCount / logsFrequency);
+		this.applied = 0;
+
+		/**
+		 * Resets applied transactions
+		 */
+		this.reset = function () {
+			this.applied = 0;
+		};
+
+		/**
+		 * Increments applied transactions and logs the progress
+		 * - For the first and last transaction
+		 * - With given frequency
+		 */
+		this.applyNext = function () {
+			if (this.applied >= this.target) {
+				throw new Error('Cannot apply transaction over the limit: ' + this.target);
+			}
+			this.applied += 1;
+			if (this.applied === 1 || this.applied === this.target || this.applied % this.step === 1) {
+				this.log();
+			}
+		};
+
+		/**
+		 * Logs the progress
+		 */
+		this.log = function () {
+			library.logger.info(msg, ((this.applied / this.target) *  100).toPrecision(4)+ ' %' + ': applied ' + this.applied + ' of ' + this.target + ' transactions' );
+		};
+	}
+	return new BlockProgressLogger(transactionsCount, logsFrequency, msg);
+};
+
 // Shared
 shared.getBlock = function (req, cb) {
 	if (!__private.loaded) {

test/common/initModule.js

@@ -1,49 +1,96 @@
 'use strict';
 
 var express = require('express');
-var merge = require('lodash/merge');
-
 var path = require('path');
+var _ = require('lodash');
+
 var dirname = path.join(__dirname, '..', '..');
 var config = require(path.join(dirname, '/config.json'));
 var database = require(path.join(dirname, '/helpers', 'database.js'));
 var genesisblock = require(path.join(dirname, '/genesisBlock.json'));
 var Logger = require(dirname + '/logger.js');
+var z_schema = require('../../helpers/z_schema.js');
 
 var modulesLoader = new function () {
 
 	this.db = null;
 	this.logger = new Logger({ echo: null, errorLevel: config.fileLogLevel, filename: config.logFileName });
+	this.scope = {
+		config: config,
+		genesisblock: { block: genesisblock },
+		logger: this.logger,
+		network: {
+			app: express()
+		},
+		public: '../../public',
+		schema: new z_schema()
+	};
+
 	/**
+	 * Initializes Logic class with params
+	 *
+	 * @param {Function} Logic
+	 * @param {Object} scope
+	 * @param {Function} cb
+	 */
+	this.initLogic = function (Logic, scope, cb) {
+		new Logic(scope, cb);
+	};
+
+	/**
+	 * Initializes Module class with params
+	 *
 	 * @param {Function} Module
 	 * @param {Object} scope
 	 * @param {Function} cb
 	 */
-	this.init = function (Module, scope, cb) {
-		new Module(function (err, module) {
-			return cb(err, module);
-		}, merge({}, scope, {
-			network: {
-				app: express()
-			},
-			genesisblock: genesisblock
-		}));
+	this.initModule = function (Module, scope, cb) {
+		return new Module(cb, scope);
 	};
 
 	/**
+	 * Initializes Module class with basic conf
+	 *
 	 * @param {Function} Module
 	 * @param {Function} cb
+	 * @param {Object=} scope
+	 */
+	this.initModuleWithDb = function (Module, cb, scope) {
+		this.initWithDb(Module, this.initModule, cb, scope);
+	};
+
+	/**
+	 * Initializes Logic class with basic conf
+	 *
+	 * @param {Function} Logic
+	 * @param {Function} cb
+	 * @param {Object=} scope
 	 */
-	this.initWithDb = function (Module, cb) {
+	this.initLogicWithDb = function (Logic, cb, scope) {
+		this.initWithDb(Logic, this.initLogic, cb, scope);
+	};
+
+	/**
+	 * Accepts Class to invoke (Logic or Module) and fills the scope with basic conf
+	 *
+	 * @param {Function} Klass
+	 * @param {Function} moduleConstructor
+	 * @param {Function} cb
+	 * @param {Object=} scope
+	 */
+	this.initWithDb = function (Klass, moduleConstructor, cb, scope) {
 		this.getDbConnection(function (err, db) {
 			if (err) {
 				return cb(err);
 			}
-			this.init(Module, {db: db}, cb);
+
+			moduleConstructor(Klass, _.merge(this.scope, {db: db}, scope), cb);
 		}.bind(this));
 	};
 
 	/**
+	 * Starts and returns db connection
+	 *
 	 * @param {Function} cb
 	 */
 	this.getDbConnection = function (cb) {
@@ -58,7 +105,6 @@ var modulesLoader = new function () {
 			cb(null, this.db);
 		}.bind(this));
 	};
-
 };
 
 module.exports = {

test/index.js

@@ -1,6 +1,7 @@
 require('./unit/helpers/request-limiter.js');
 require('./unit/logic/blockReward.js');
 require('./unit/modules/peers.js');
+require('./unit/modules/blocks.js');
 
 require('./api/accounts.js');
 require('./api/blocks.js');

test/unit/modules/blocks.js

@@ -0,0 +1,51 @@
+'use strict';
+
+var chai = require('chai');
+var express = require('express');
+var sinon = require('sinon');
+var node = require('../../node.js');
+
+var modulesLoader = require('../../common/initModule').modulesLoader;
+var Blocks = require('../../../modules/blocks');
+
+describe('blocks', function () {
+
+	var blocks;
+
+	before(function (done) {
+		modulesLoader.initModuleWithDb(Blocks, function (err, __blocks) {
+			if (err) {
+				return done(err);
+			}
+			blocks = __blocks;
+			done();
+		});
+	});
+
+	describe('getBlockProgressLogger', function () {
+
+		it('should logs correctly', function () {
+			var tracker = blocks.getBlockProgressLogger(5, 2, '');
+			tracker.log = sinon.spy();
+			node.expect(tracker.applied).to.equals(0);
+			node.expect(tracker.step).to.equals(2);
+			tracker.applyNext();
+			node.expect(tracker.log.calledOnce).to.ok;
+			node.expect(tracker.applied).to.equals(1);
+			tracker.applyNext();
+			node.expect(tracker.log.calledTwice).to.not.ok;
+			node.expect(tracker.applied).to.equals(2);
+			tracker.applyNext();
+			node.expect(tracker.log.calledTwice).to.ok;
+			node.expect(tracker.applied).to.equals(3);
+			tracker.applyNext();
+			node.expect(tracker.log.calledThrice).to.not.ok;
+			node.expect(tracker.applied).to.equals(4);
+			tracker.applyNext();
+			node.expect(tracker.log.calledThrice).to.ok;
+			node.expect(tracker.applied).to.equals(5);
+
+			node.expect(tracker.applyNext.bind(tracker)).to.throw('Cannot apply transaction over the limit: 5');
+		});
+	});
+});