Merge pull request #146 from shirish87/trace

Finer logging + handle worker lookup failure

Author: nakula

bin/cli.js

@@ -3,7 +3,7 @@
 var todo = process.argv[2];
 
 if (todo === '--verbose') {
-  global.logLevel = 'debug';
+  global.logLevel = process.env.LOG_LEVEL || 'debug';
 } else {
   global.logLevel = 'info';
 }
@@ -40,7 +40,11 @@ var Log = require('../lib/logger'),
     tunnel;
 
 function terminateAllWorkers(callback) {
+  logger.trace('terminateAllWorkers');
+
   var cleanWorker = function(id, key) {
+    logger.trace('cleanWorker(%s, %s)', id, key);
+
     client.terminateWorker(id, function() {
       var worker = workers[key];
       if(worker) {
@@ -52,12 +56,14 @@ function terminateAllWorkers(callback) {
         delete workerKeys[worker.id];
       }
       if (utils.objectSize(workers) === 0) {
+        logger.trace('terminateAllWorkers: done');
         callback();
       }
     });
   };
 
   if (utils.objectSize(workers) === 0) {
+    logger.trace('terminateAllWorkers: done');
     callback();
   } else {
     for (var key in workers){
@@ -67,6 +73,7 @@ function terminateAllWorkers(callback) {
       } else {
         delete workers[key];
         if (utils.objectSize(workers) === 0) {
+          logger.trace('terminateAllWorkers: done');
           callback();
         }
       }
@@ -75,6 +82,8 @@ function terminateAllWorkers(callback) {
 }
 
 function cleanUpAndExit(signal, status) {
+  logger.trace('cleanUpAndExit: signal: %s', signal);
+
   try {
     server.close();
   } catch (e) {
@@ -113,6 +122,7 @@ function getTestBrowserInfo(browserString, path) {
     info += ', ' + path;
   }
 
+  logger.trace('getTestBrowserInfo(%s, %s): %s', browserString, path, info);
   return info;
 }
 
@@ -126,11 +136,13 @@ function buildTestUrl(test_path, worker_key, browser_string) {
   });
 
   url += ((url.indexOf('?') > 0) ? '&' : '?') + querystring;
+  logger.trace('buildTestUrl:', url);
   return url;
 }
 
 
 function launchServer() {
+  logger.trace('launchServer:', serverPort);
   logger.debug('Launching server on port:', serverPort);
 
   server = new Server(client, workers);
@@ -165,7 +177,11 @@ function launchBrowser(browser, path) {
   activityTimeout = timeout - 10;
   ackTimeout = parseInt(config.ackTimeout) || 60;
 
+  logger.trace('[%s] client.createWorker', browserInfo, browser);
+
   client.createWorker(browser, function (err, worker) {
+    logger.trace('[%s] client.createWorker | response:', browserInfo, worker, err);
+
     if (err || typeof worker !== 'object') {
       logger.info('Error from BrowserStack: ', err);
       utils.alertBrowserStack('Failed to launch worker',
@@ -191,6 +207,8 @@ function launchBrowser(browser, path) {
 
 function launchBrowsers(config, browser) {
   setTimeout(function () {
+    logger.trace('launchBrowsers', browser);
+
     if (Array.isArray(config.test_path)){
       config.multipleTest = config.test_path.length > 1? true : false;
       launchBrowser(browser, config.test_path[0]);
@@ -207,7 +225,9 @@ function attachWorkerHelpers(worker) {
 
   worker.buildUrl = function buildUrl(test_path) {
     var workerKey = workerKeys[this.id] ? workerKeys[this.id].key : null;
-    return buildTestUrl(test_path || this.test_path, workerKey, this.getTestBrowserInfo());
+    var url = buildTestUrl(test_path || this.test_path, workerKey, this.getTestBrowserInfo());
+    logger.trace('[%s] worker.buildUrl: %s', this.id, url);
+    return url;
   };
 
   worker.getTestBrowserInfo = function getTestBrowserInfo(test_path) {
@@ -222,18 +242,23 @@ function attachWorkerHelpers(worker) {
     var self = this;
 
     if (this.ackTimeout) {
-      // Already awaiting ack, or awaited ack once and failed
+      logger.trace('[%s] worker.awaitAck: already awaiting ack, or awaited ack once and failed', self.id);
       return;
     }
 
+    logger.trace('[%s] worker.awaitAck: timeout in %d secs', self.id, ackTimeout);
+
     this.ackTimeout = setTimeout(function () {
       if (self.isAckd) {
-        // Already ack'd
+        logger.trace('[%s] worker.awaitAck: already ackd', self.id);
         return;
       }
 
-      // worker has not acknowledged itself in 60 sec, reopen url
-      client.changeUrl(self.id, { url: self.buildUrl() }, function () {
+      var url = self.buildUrl();
+      logger.trace('[%s] worker.awaitAck: client.changeUrl: %s', self.id, url);
+
+      client.changeUrl(self.id, { url: url }, function (err, data) {
+        logger.trace('[%s] worker.awaitAck: client.changeUrl: %s | response:', self.id, url, data, err);
         logger.debug('[%s] Sent Request to reload url', self.getTestBrowserInfo());
       });
 
@@ -246,10 +271,13 @@ function attachWorkerHelpers(worker) {
     this.resetAck();
     this.isAckd = true;
 
+    logger.trace('[%s] worker.markAckd', this.id);
     logger.debug('[%s] Received ack', this.getTestBrowserInfo());
   };
 
   worker.resetAck = function resetAck() {
+    logger.trace('[%s] worker.resetAck', this.id);
+
     clearTimeout(this.ackTimeout);
     this.ackTimeout = null;
     this.isAckd = false;
@@ -263,8 +291,12 @@ var statusPoller = {
   poller: null,
 
   start: function() {
+    logger.trace('statusPoller.start');
+
     statusPoller.poller = setInterval(function () {
       client.getWorkers(function (err, _workers) {
+        logger.trace('client.getWorkers | response: worker count: %d', (_workers || []).length, err);
+
         if (!_workers) {
           logger.info(chalk.red('Error found: ' + err));
           return;
@@ -286,9 +318,12 @@ var statusPoller = {
 
             // Await ack from browser-worker
             worker.awaitAck();
+            logger.trace('[%s] worker.activityTimeout: timeout in %d secs', worker.id, activityTimeout);
 
             worker.activityTimeout = setTimeout(function () {
               if (!worker.isAckd) {
+                logger.trace('[%s] worker.activityTimeout', worker.id);
+
                 var subject = 'Worker inactive for too long: ' + worker.string;
                 var content = 'Worker details:\n' + JSON.stringify(worker.config, null, 4);
                 utils.alertBrowserStack(subject, content, null, function(){});
@@ -303,13 +338,21 @@ var statusPoller = {
                     config.status = 1;
                   }
 
+                  logger.trace('[%s] worker.activityTimeout: all tests done', worker.id, config.status && 'with failures');
                   process.exit('SIGTERM');
                 }
+              } else {
+                logger.trace('[%s] worker.activityTimeout: already ackd', worker.id);
               }
             }, activityTimeout * 1000);
 
+
+            logger.trace('[%s] worker.testActivityTimeout: timeout in %d secs', worker.id, activityTimeout);
+
             worker.testActivityTimeout = setTimeout(function () {
               if (worker.isAckd) {
+                logger.trace('[%s] worker.testActivityTimeout', worker.id);
+
                 var subject = 'Tests timed out on: ' + worker.string;
                 var content = 'Worker details:\n' + JSON.stringify(worker.config, null, 4);
                 utils.alertBrowserStack(subject, content, null, function(){});
@@ -324,8 +367,11 @@ var statusPoller = {
                     config.status = 1;
                   }
 
+                  logger.trace('[%s] worker.testActivityTimeout: all tests done', worker.id, config.status && 'with failures');
                   process.exit('SIGTERM');
                 }
+              } else {
+                logger.trace('[%s] worker.testActivityTimeout: not ackd', worker.id);
               }
             }, (activityTimeout * 1000));
           }
@@ -335,12 +381,15 @@ var statusPoller = {
   },
 
   stop: function() {
+    logger.trace('statusPoller.poller');
     clearInterval(statusPoller.poller);
   }
 };
 
 function runTests() {
   if (config.proxy) {
+    logger.trace('runTests: with proxy', config.proxy);
+
     tunnelingAgent = tunnel.httpOverHttp({
       proxy: config.proxy
     });
@@ -353,15 +402,21 @@ function runTests() {
   if (config.browsers && config.browsers.length > 0) {
     ConfigParser.parse(client, config.browsers, function(browsers){
       launchServer();
+
+      logger.trace('runTests: creating tunnel');
       tunnel = new Tunnel(config.key, serverPort, config.tunnelIdentifier, function () {
+        logger.trace('runTests: created tunnel');
+
         statusPoller.start();
         var total_runs = config.browsers.length * (Array.isArray(config.test_path) ? config.test_path.length : 1);
         logger.info('Launching ' + config.browsers.length + ' worker(s) for ' + total_runs + ' run(s).');
         browsers.forEach(function(browser) {
           if (browser.browser_version === 'latest') {
             logger.debug('[%s] Finding version.', utils.browserString(browser));
+            logger.trace('runTests: client.getLatest');
 
             client.getLatest(browser, function(err, version) {
+              logger.trace('runTests: client.getLatest | response:', version, err);
               logger.debug('[%s] Version is %s.',
                            utils.browserString(browser), version);
                            browser.browser_version = version;

lib/logger.js

@@ -1,5 +1,5 @@
 var fmt = require('util').format;
-var logLevels = {ERROR: 3, INFO: 6, DEBUG: 7};
+var logLevels = {ERROR: 3, INFO: 6, DEBUG: 7, TRACE: 8};
 
 function Log(level){
   if ('string' === typeof level) {
@@ -29,6 +29,10 @@ Log.prototype = {
 
   debug: function(){
     this.log('DEBUG', arguments);
+  },
+
+  trace: function(){
+    this.log('TRACE', arguments);
   }
 };