Skip to content

Commit

Permalink
Added finer log level: trace
Browse files Browse the repository at this point in the history
  • Loading branch information
@shirish87
shirish87 committed Jan 23, 2016
1 parent 7e4d813 commit 4ab2993
Show file tree
Hide file tree
Showing 3 changed files with 95 additions and 9 deletions.
67 changes: 61 additions & 6 deletions bin/cli.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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';
}
Expand Down Expand Up @@ -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) {
Expand All @@ -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){
Expand All @@ -67,6 +73,7 @@ function terminateAllWorkers(callback) {
} else {
delete workers[key];
if (utils.objectSize(workers) === 0) {
logger.trace('terminateAllWorkers: done');
callback();
}
}
Expand All @@ -75,6 +82,8 @@ function terminateAllWorkers(callback) {
}

function cleanUpAndExit(signal, status) {
logger.trace('cleanUpAndExit: signal: %s', signal);

try {
server.close();
} catch (e) {
Expand Down Expand Up @@ -113,6 +122,7 @@ function getTestBrowserInfo(browserString, path) {
info += ', ' + path;
}

logger.trace('getTestBrowserInfo(%s, %s): %s', browserString, path, info);
return info;
}

Expand All @@ -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);
Expand Down Expand Up @@ -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',
Expand All @@ -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]);
Expand All @@ -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) {
Expand All @@ -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());
});

Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -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(){});
Expand All @@ -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(){});
Expand All @@ -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));
}
Expand All @@ -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
});
Expand All @@ -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;
Expand Down
6 changes: 5 additions & 1 deletion lib/logger.js
View file
Original file line number Diff line number Diff line change
@@ -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) {
Expand Down Expand Up @@ -29,6 +29,10 @@ Log.prototype = {

debug: function(){
this.log('DEBUG', arguments);
},

trace: function(){
this.log('TRACE', arguments);
}
};

Expand Down
31 changes: 29 additions & 2 deletions lib/server.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -194,7 +194,13 @@ exports.Server = function Server(bsClient, workers) {

function getWorkerUuid(request) {
var uuid = request.headers['x-worker-uuid'];

uuid = uuid && uuid.replace(/[^a-zA-Z0-9\-]/, '');
logger.trace('cleaning up worker uuid:', uuid);

uuid = (uuid && typeof workers[uuid] === 'object') ? uuid : null;
logger.trace('worker uuid', uuid, (uuid ? 'valid' : 'invalid'));

return (uuid && workers[uuid]) ? uuid : null;
}

Expand Down Expand Up @@ -230,6 +236,8 @@ exports.Server = function Server(bsClient, workers) {
logger.info('[%s] Log: ' + qs.parse(body).data, worker.string);
}

logger.trace('[%s] _progress', worker.id, query);

if (query && query.tracebacks) {
query.tracebacks.forEach(function(traceback) {
logger.info('[%s] ' + chalk.red('Error:'), worker.getTestBrowserInfo(), formatTraceback(traceback));
Expand All @@ -253,6 +261,8 @@ exports.Server = function Server(bsClient, workers) {
query = parseBody(body);
} catch (e) {}

logger.trace('[%s] _report', worker.id, query);

if (query === null) {
logger.info('[%s] Null response from remote Browser', request.headers['x-browser-string']);
} else {
Expand All @@ -267,23 +277,30 @@ exports.Server = function Server(bsClient, workers) {
config.status += query.failed;
}

logger.trace('[%s] _report: client.takeScreenshot', worker.id);

bsClient.takeScreenshot(worker.id, function(error, screenshot) {
logger.trace('[%s] _report: client.takeScreenshot | response:', worker.id, screenshot, error);

if (!error && screenshot.url && query && query.failed) {
logger.info('[%s] ' + chalk.yellow('Screenshot:') + ' %s', worker.getTestBrowserInfo(), screenshot.url);
}

checkAndTerminateWorker(worker, function(reusedWorker) {
if (!workers[uuid]) {
logger.trace('[%s] _report: checkAndTerminateWorker: worker not found', worker.id);
return;
}

if (reusedWorker) {
logger.trace('[%s] _report: checkAndTerminateWorker: reused worker', worker.id);
logger.debug('[%s] Reused', worker.getTestBrowserInfo());
worker.resetAck();
worker.awaitAck();
return;
}

logger.trace('[%s] _report: checkAndTerminateWorker: terminated', worker.id);
logger.debug('[%s] Terminated', worker.getTestBrowserInfo());

clearTimeout(workers[uuid].ackTimeout);
Expand All @@ -299,6 +316,7 @@ exports.Server = function Server(bsClient, workers) {
config.status = 1;
}

logger.trace('[%s] _report: checkAndTerminateWorker: all tests done', worker.id, config.status && 'with failures');
process.exit('SIGTERM');
}
});
Expand All @@ -307,15 +325,24 @@ exports.Server = function Server(bsClient, workers) {
response.end();
},
'_log': function logHandler(uri, body, request, response) {
var uuid = getWorkerUuid(request);
var query = parseBody(body);

logger.trace('[%s] _log', ((uuid && workers[uuid]) || {}).id, query);
logger.info('[' + request.headers['x-browser-string'] + '] ' + query);
response.end();
},
'_patch': function patchHandler(uri, body, request, response) {
handleFile(path.join(__dirname, uri), request, response, true);
var filePath = path.join(__dirname, uri);
logger.trace('_patch', filePath);

handleFile(filePath, request, response, true);
},
'_default': function defaultHandler(uri, body, request, response) {
handleFile(path.join(process.cwd(), uri), request, response);
var filePath = path.join(process.cwd(), uri);
logger.trace('_default', filePath);

handleFile(filePath, request, response);
}
};

Expand Down

0 comments on commit 4ab2993

Please sign in to comment.