add new test, and better logs

lib/blockchainexplorers/insight.js

@@ -41,6 +41,16 @@ Insight.prototype._doRequest = function(args, cb) {
       'User-Agent': this.userAgent,
     }
   };
+
+  if (log.level == 'verbose') {
+    var s  = JSON.stringify(args);
+
+    if ( s.length > 100 ) 
+      s= s.substr(0,100) + '...';
+    
+    log.debug('', 'Insight Q: %s', s);
+  }
+
   requestList(_.defaults(args, opts), cb);
 };
 
@@ -59,9 +69,10 @@ Insight.prototype.getUtxos = function(addresses, cb) {
     json: {
       addrs: _.uniq([].concat(addresses)).join(',')
     },
-    timeout: 120000,
   };
 
+  log.info('','Querying utxos: %s addrs', addresses.length);
+
   this._doRequest(args, function(err, res, unspent) {
     if (err || res.statusCode !== 200) return cb(_parseErr(err, res));
     return cb(null, unspent);
@@ -122,6 +133,9 @@ Insight.prototype.getTransactions = function(addresses, from, to, cb) {
     timeout: 120000,
   };
 
+
+  log.info('','Querying addresses: %s addrs', addresses.length);
+
   this._doRequest(args, function(err, res, txs) {
     if (err || res.statusCode !== 200) return cb(_parseErr(err, res));
 

lib/blockchainexplorers/request-list.js

@@ -31,11 +31,23 @@ var requestList = function(args, cb) {
   async.whilst(
     function() {
       nextUrl = urls.shift();
+      if (!nextUrl && success === 'false') 
+        log.warn('no more servers to test for the request');
       return nextUrl && !success;
     },
     function(a_cb) {
       args.uri = nextUrl;
+
+      var time = 0;
+      var interval = setInterval(function() {
+        time += 10;
+        log.debug('', 'Delayed insight query: %s, time: %d s', args.uri, time);
+      }, 10000);
+
       request(args, function(err, res, body) {
+        clearInterval(interval);
+        sucess = false;
+
         if (err) {
           log.warn('REQUEST FAIL: ' + nextUrl + ' ERROR: ' + err);
         }

lib/errors/errordefinitions.js

@@ -33,7 +33,7 @@ var errors = {
   UPGRADE_NEEDED: 'Client app needs to be upgraded',
   WALLET_ALREADY_EXISTS: 'Wallet already exists',
   WALLET_FULL: 'Wallet full',
-  WALLET_LOCKED: 'Wallet is busy, try later',
+  WALLET_BUSY: 'Wallet is busy, try later',
   WALLET_NOT_COMPLETE: 'Wallet is not complete',
   WALLET_NOT_FOUND: 'Wallet not found',
 };

lib/expressapp.js

@@ -17,7 +17,7 @@ var Stats = require('./stats');
 
 log.disableColor();
 log.debug = log.verbose;
-log.level = 'info';
+log.level = 'verbose';
 
 var ExpressApp = function() {
   this.app = express();
@@ -75,14 +75,10 @@ ExpressApp.prototype.start = function(opts, cb) {
   } else {
     var morgan = require('morgan');
     morgan.token('walletId', function getId(req) {
-      return req.walletId
+      return req.walletId ?  '<' + req.walletId + '>' :  '<>';
     });
 
-    morgan.token('copayerId', function getId(req) {
-      return req.copayerId
-    });
-
-    var logFormat = ':remote-addr :date[iso] ":method :url" :status :res[content-length] :response-time ":user-agent" :walletId :copayerId';
+    var logFormat = ':walletId :remote-addr :date[iso] ":method :url" :status :res[content-length] :response-time ":user-agent"  ';
     var logOpts = {
       skip: function(req, res) {
         if (res.statusCode != 200) return false;
@@ -141,6 +137,7 @@ ExpressApp.prototype.start = function(opts, cb) {
   };
 
   function getServer(req, res) {
+    log.heading = '<>';
     var opts = {
       clientVersion: req.header('x-client-version'),
     };
@@ -183,6 +180,8 @@ ExpressApp.prototype.start = function(opts, cb) {
       req.walletId = server.walletId;
       req.copayerId = server.copayerId;
 
+      log.heading = '<' + req.walletId + '>';
+
       return cb(server);
     });
   };

lib/lock.js

@@ -31,7 +31,7 @@ Lock.prototype.runLocked = function(token, cb, task) {
   $.shouldBeDefined(token);
 
   this.lock.locked(token, 5 * 1000, 5 * 60 * 1000, function(err, release) {
-    if (err) return cb(Errors.WALLET_LOCKED);
+    if (err) return cb(Errors.WALLET_BUSY);
     var _cb = function() {
       cb.apply(null, arguments);
       release();

lib/server.js

@@ -1399,11 +1399,13 @@ WalletService.prototype.getBalance = function(opts, cb, i) {
             var now = Math.floor(Date.now() / 1000);
 
             if (twoStepCache.lastEmpty > now - Defaults.TWO_STEP_INACTIVE_CLEAN_DURATION_MIN * 60 )  {
+              log.debug('Not running the FULL balance query due to TWO_STEP_INACTIVE_CLEAN_DURATION_MIN ');
               return;
             }
 
 
             setTimeout(function() {
+              log.debug('Running full balance query');
               self._getBalanceOneStep(opts, function(err, fullBalance) {
                 if (err) return;
                 if (!_.isEqual(partialBalance, fullBalance)) {

test/integration/server.js

@@ -2335,6 +2335,78 @@ describe('Wallet service', function() {
       });
     });
 
+  it('should do 2 steps if called 2 times given the first one there found no funds on non-active addresses, but times passes', function(done) {
+      var oldAddrs, newAddrs, spy;
+
+      async.series([
+        function(next) {
+          spy = sinon.spy(server, '_getBalanceOneStep');
+          helpers.createAddresses(server, wallet, 2, 0, function(addrs) {
+            oldAddrs = addrs;
+            next();
+          });
+        },
+        function(next) {
+          clock.tick(7 * Defaults.TWO_STEP_CREATION_HOURS * 3600 * 1000);
+          helpers.createAddresses(server, wallet, 2, 0, function(addrs) {
+            newAddrs = addrs;
+            helpers.stubUtxos(server, wallet, [1, 2], {
+              addresses: newAddrs,
+            }, function() {
+              next();
+            });
+          });
+        },
+        function(next) {
+          server.getBalance({
+            twoStep: true
+          }, function(err, balance) {
+            should.not.exist(err);
+            should.exist(balance);
+            balance.totalAmount.should.equal(helpers.toSatoshi(3));
+            next();
+          });
+        },
+        function(next) {
+          setTimeout(next, 100);
+        },
+        // Should _oneStep should be called once
+        function(next) {
+          spy.calledOnce.should.equal(true);
+          next();
+        },
+        function(next) {
+          helpers.stubUtxos(server, wallet, 0.5, {
+            addresses: newAddrs[0],
+            keepUtxos: true,
+          }, function() {
+            clock.tick(2 * Defaults.TWO_STEP_INACTIVE_CLEAN_DURATION_MIN * 60 * 1000);
+            next();
+          });
+        },
+        function(next) {
+          server.getBalance({
+            twoStep: true
+          }, function(err, balance) {
+            should.not.exist(err);
+            should.exist(balance);
+            balance.totalAmount.should.equal(helpers.toSatoshi(3.5));
+            next();
+          });
+        },
+        function(next) {
+          setTimeout(next, 100);
+        },
+        function(next) {
+          spy.calledTwice.should.equal(true);
+          next();
+        },
+      ], function(err) {
+        should.not.exist(err);
+        done();
+      });
+    });
+
   it('should do 2 steps if called 2 times given the first one there found funds on non-active addresses', function(done) {
       var oldAddrs, newAddrs, spy, notificationCount;