Skip to content

Commit 4ab2993

Browse files
shirish87shirish87
committed
Added finer log level: trace
1 parent 7e4d813 commit 4ab2993

File tree

3 files changed

+95
-9
lines changed

3 files changed

+95
-9
lines changed

‎bin/cli.js‎

Lines changed: 61 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
var todo = process.argv[2];
44

55
if (todo === '--verbose') {
6-
global.logLevel = 'debug';
6+
global.logLevel = process.env.LOG_LEVEL || 'debug';
77
} else {
88
global.logLevel = 'info';
99
}
@@ -40,7 +40,11 @@ var Log = require('../lib/logger'),
4040
tunnel;
4141

4242
function terminateAllWorkers(callback) {
43+
logger.trace('terminateAllWorkers');
44+
4345
var cleanWorker = function(id, key) {
46+
logger.trace('cleanWorker(%s, %s)', id, key);
47+
4448
client.terminateWorker(id, function() {
4549
var worker = workers[key];
4650
if(worker) {
@@ -52,12 +56,14 @@ function terminateAllWorkers(callback) {
5256
delete workerKeys[worker.id];
5357
}
5458
if (utils.objectSize(workers) === 0) {
59+
logger.trace('terminateAllWorkers: done');
5560
callback();
5661
}
5762
});
5863
};
5964

6065
if (utils.objectSize(workers) === 0) {
66+
logger.trace('terminateAllWorkers: done');
6167
callback();
6268
} else {
6369
for (var key in workers){
@@ -67,6 +73,7 @@ function terminateAllWorkers(callback) {
6773
} else {
6874
delete workers[key];
6975
if (utils.objectSize(workers) === 0) {
76+
logger.trace('terminateAllWorkers: done');
7077
callback();
7178
}
7279
}
@@ -75,6 +82,8 @@ function terminateAllWorkers(callback) {
7582
}
7683

7784
function cleanUpAndExit(signal, status) {
85+
logger.trace('cleanUpAndExit: signal: %s', signal);
86+
7887
try {
7988
server.close();
8089
} catch (e) {
@@ -113,6 +122,7 @@ function getTestBrowserInfo(browserString, path) {
113122
info += ', ' + path;
114123
}
115124

125+
logger.trace('getTestBrowserInfo(%s, %s): %s', browserString, path, info);
116126
return info;
117127
}
118128

@@ -126,11 +136,13 @@ function buildTestUrl(test_path, worker_key, browser_string) {
126136
});
127137

128138
url += ((url.indexOf('?') > 0) ? '&' : '?') + querystring;
139+
logger.trace('buildTestUrl:', url);
129140
return url;
130141
}
131142

132143

133144
function launchServer() {
145+
logger.trace('launchServer:', serverPort);
134146
logger.debug('Launching server on port:', serverPort);
135147

136148
server = new Server(client, workers);
@@ -165,7 +177,11 @@ function launchBrowser(browser, path) {
165177
activityTimeout = timeout - 10;
166178
ackTimeout = parseInt(config.ackTimeout) || 60;
167179

180+
logger.trace('[%s] client.createWorker', browserInfo, browser);
181+
168182
client.createWorker(browser, function (err, worker) {
183+
logger.trace('[%s] client.createWorker | response:', browserInfo, worker, err);
184+
169185
if (err || typeof worker !== 'object') {
170186
logger.info('Error from BrowserStack: ', err);
171187
utils.alertBrowserStack('Failed to launch worker',
@@ -191,6 +207,8 @@ function launchBrowser(browser, path) {
191207

192208
function launchBrowsers(config, browser) {
193209
setTimeout(function () {
210+
logger.trace('launchBrowsers', browser);
211+
194212
if (Array.isArray(config.test_path)){
195213
config.multipleTest = config.test_path.length > 1? true : false;
196214
launchBrowser(browser, config.test_path[0]);
@@ -207,7 +225,9 @@ function attachWorkerHelpers(worker) {
207225

208226
worker.buildUrl = function buildUrl(test_path) {
209227
var workerKey = workerKeys[this.id] ? workerKeys[this.id].key : null;
210-
return buildTestUrl(test_path || this.test_path, workerKey, this.getTestBrowserInfo());
228+
var url = buildTestUrl(test_path || this.test_path, workerKey, this.getTestBrowserInfo());
229+
logger.trace('[%s] worker.buildUrl: %s', this.id, url);
230+
return url;
211231
};
212232

213233
worker.getTestBrowserInfo = function getTestBrowserInfo(test_path) {
@@ -222,18 +242,23 @@ function attachWorkerHelpers(worker) {
222242
var self = this;
223243

224244
if (this.ackTimeout) {
225-
// Already awaiting ack, or awaited ack once and failed
245+
logger.trace('[%s] worker.awaitAck: already awaiting ack, or awaited ack once and failed', self.id);
226246
return;
227247
}
228248

249+
logger.trace('[%s] worker.awaitAck: timeout in %d secs', self.id, ackTimeout);
250+
229251
this.ackTimeout = setTimeout(function () {
230252
if (self.isAckd) {
231-
// Already ack'd
253+
logger.trace('[%s] worker.awaitAck: already ackd', self.id);
232254
return;
233255
}
234256

235-
// worker has not acknowledged itself in 60 sec, reopen url
236-
client.changeUrl(self.id, { url: self.buildUrl() }, function () {
257+
var url = self.buildUrl();
258+
logger.trace('[%s] worker.awaitAck: client.changeUrl: %s', self.id, url);
259+
260+
client.changeUrl(self.id, { url: url }, function (err, data) {
261+
logger.trace('[%s] worker.awaitAck: client.changeUrl: %s | response:', self.id, url, data, err);
237262
logger.debug('[%s] Sent Request to reload url', self.getTestBrowserInfo());
238263
});
239264

@@ -246,10 +271,13 @@ function attachWorkerHelpers(worker) {
246271
this.resetAck();
247272
this.isAckd = true;
248273

274+
logger.trace('[%s] worker.markAckd', this.id);
249275
logger.debug('[%s] Received ack', this.getTestBrowserInfo());
250276
};
251277

252278
worker.resetAck = function resetAck() {
279+
logger.trace('[%s] worker.resetAck', this.id);
280+
253281
clearTimeout(this.ackTimeout);
254282
this.ackTimeout = null;
255283
this.isAckd = false;
@@ -263,8 +291,12 @@ var statusPoller = {
263291
poller: null,
264292

265293
start: function() {
294+
logger.trace('statusPoller.start');
295+
266296
statusPoller.poller = setInterval(function () {
267297
client.getWorkers(function (err, _workers) {
298+
logger.trace('client.getWorkers | response: worker count: %d', (_workers || []).length, err);
299+
268300
if (!_workers) {
269301
logger.info(chalk.red('Error found: ' + err));
270302
return;
@@ -286,9 +318,12 @@ var statusPoller = {
286318

287319
// Await ack from browser-worker
288320
worker.awaitAck();
321+
logger.trace('[%s] worker.activityTimeout: timeout in %d secs', worker.id, activityTimeout);
289322

290323
worker.activityTimeout = setTimeout(function () {
291324
if (!worker.isAckd) {
325+
logger.trace('[%s] worker.activityTimeout', worker.id);
326+
292327
var subject = 'Worker inactive for too long: ' + worker.string;
293328
var content = 'Worker details:\n' + JSON.stringify(worker.config, null, 4);
294329
utils.alertBrowserStack(subject, content, null, function(){});
@@ -303,13 +338,21 @@ var statusPoller = {
303338
config.status = 1;
304339
}
305340

341+
logger.trace('[%s] worker.activityTimeout: all tests done', worker.id, config.status && 'with failures');
306342
process.exit('SIGTERM');
307343
}
344+
} else {
345+
logger.trace('[%s] worker.activityTimeout: already ackd', worker.id);
308346
}
309347
}, activityTimeout * 1000);
310348

349+
350+
logger.trace('[%s] worker.testActivityTimeout: timeout in %d secs', worker.id, activityTimeout);
351+
311352
worker.testActivityTimeout = setTimeout(function () {
312353
if (worker.isAckd) {
354+
logger.trace('[%s] worker.testActivityTimeout', worker.id);
355+
313356
var subject = 'Tests timed out on: ' + worker.string;
314357
var content = 'Worker details:\n' + JSON.stringify(worker.config, null, 4);
315358
utils.alertBrowserStack(subject, content, null, function(){});
@@ -324,8 +367,11 @@ var statusPoller = {
324367
config.status = 1;
325368
}
326369

370+
logger.trace('[%s] worker.testActivityTimeout: all tests done', worker.id, config.status && 'with failures');
327371
process.exit('SIGTERM');
328372
}
373+
} else {
374+
logger.trace('[%s] worker.testActivityTimeout: not ackd', worker.id);
329375
}
330376
}, (activityTimeout * 1000));
331377
}
@@ -335,12 +381,15 @@ var statusPoller = {
335381
},
336382

337383
stop: function() {
384+
logger.trace('statusPoller.poller');
338385
clearInterval(statusPoller.poller);
339386
}
340387
};
341388

342389
function runTests() {
343390
if (config.proxy) {
391+
logger.trace('runTests: with proxy', config.proxy);
392+
344393
tunnelingAgent = tunnel.httpOverHttp({
345394
proxy: config.proxy
346395
});
@@ -353,15 +402,21 @@ function runTests() {
353402
if (config.browsers && config.browsers.length > 0) {
354403
ConfigParser.parse(client, config.browsers, function(browsers){
355404
launchServer();
405+
406+
logger.trace('runTests: creating tunnel');
356407
tunnel = new Tunnel(config.key, serverPort, config.tunnelIdentifier, function () {
408+
logger.trace('runTests: created tunnel');
409+
357410
statusPoller.start();
358411
var total_runs = config.browsers.length * (Array.isArray(config.test_path) ? config.test_path.length : 1);
359412
logger.info('Launching ' + config.browsers.length + ' worker(s) for ' + total_runs + ' run(s).');
360413
browsers.forEach(function(browser) {
361414
if (browser.browser_version === 'latest') {
362415
logger.debug('[%s] Finding version.', utils.browserString(browser));
416+
logger.trace('runTests: client.getLatest');
363417

364418
client.getLatest(browser, function(err, version) {
419+
logger.trace('runTests: client.getLatest | response:', version, err);
365420
logger.debug('[%s] Version is %s.',
366421
utils.browserString(browser), version);
367422
browser.browser_version = version;

‎lib/logger.js‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
var fmt = require('util').format;
2-
var logLevels = {ERROR: 3, INFO: 6, DEBUG: 7};
2+
var logLevels = {ERROR: 3, INFO: 6, DEBUG: 7, TRACE: 8};
33

44
function Log(level){
55
if ('string' === typeof level) {
@@ -29,6 +29,10 @@ Log.prototype = {
2929

3030
debug: function(){
3131
this.log('DEBUG', arguments);
32+
},
33+
34+
trace: function(){
35+
this.log('TRACE', arguments);
3236
}
3337
};
3438

‎lib/server.js‎

Lines changed: 29 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -194,7 +194,13 @@ exports.Server = function Server(bsClient, workers) {
194194

195195
function getWorkerUuid(request) {
196196
var uuid = request.headers['x-worker-uuid'];
197+
197198
uuid = uuid && uuid.replace(/[^a-zA-Z0-9\-]/, '');
199+
logger.trace('cleaning up worker uuid:', uuid);
200+
201+
uuid = (uuid && typeof workers[uuid] === 'object') ? uuid : null;
202+
logger.trace('worker uuid', uuid, (uuid ? 'valid' : 'invalid'));
203+
198204
return (uuid && workers[uuid]) ? uuid : null;
199205
}
200206

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

239+
logger.trace('[%s] _progress', worker.id, query);
240+
233241
if (query && query.tracebacks) {
234242
query.tracebacks.forEach(function(traceback) {
235243
logger.info('[%s] ' + chalk.red('Error:'), worker.getTestBrowserInfo(), formatTraceback(traceback));
@@ -253,6 +261,8 @@ exports.Server = function Server(bsClient, workers) {
253261
query = parseBody(body);
254262
} catch (e) {}
255263

264+
logger.trace('[%s] _report', worker.id, query);
265+
256266
if (query === null) {
257267
logger.info('[%s] Null response from remote Browser', request.headers['x-browser-string']);
258268
} else {
@@ -267,23 +277,30 @@ exports.Server = function Server(bsClient, workers) {
267277
config.status += query.failed;
268278
}
269279

280+
logger.trace('[%s] _report: client.takeScreenshot', worker.id);
281+
270282
bsClient.takeScreenshot(worker.id, function(error, screenshot) {
283+
logger.trace('[%s] _report: client.takeScreenshot | response:', worker.id, screenshot, error);
284+
271285
if (!error && screenshot.url && query && query.failed) {
272286
logger.info('[%s] ' + chalk.yellow('Screenshot:') + ' %s', worker.getTestBrowserInfo(), screenshot.url);
273287
}
274288

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

280295
if (reusedWorker) {
296+
logger.trace('[%s] _report: checkAndTerminateWorker: reused worker', worker.id);
281297
logger.debug('[%s] Reused', worker.getTestBrowserInfo());
282298
worker.resetAck();
283299
worker.awaitAck();
284300
return;
285301
}
286302

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

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

319+
logger.trace('[%s] _report: checkAndTerminateWorker: all tests done', worker.id, config.status && 'with failures');
302320
process.exit('SIGTERM');
303321
}
304322
});
@@ -307,15 +325,24 @@ exports.Server = function Server(bsClient, workers) {
307325
response.end();
308326
},
309327
'_log': function logHandler(uri, body, request, response) {
328+
var uuid = getWorkerUuid(request);
310329
var query = parseBody(body);
330+
331+
logger.trace('[%s] _log', ((uuid && workers[uuid]) || {}).id, query);
311332
logger.info('[' + request.headers['x-browser-string'] + '] ' + query);
312333
response.end();
313334
},
314335
'_patch': function patchHandler(uri, body, request, response) {
315-
handleFile(path.join(__dirname, uri), request, response, true);
336+
var filePath = path.join(__dirname, uri);
337+
logger.trace('_patch', filePath);
338+
339+
handleFile(filePath, request, response, true);
316340
},
317341
'_default': function defaultHandler(uri, body, request, response) {
318-
handleFile(path.join(process.cwd(), uri), request, response);
342+
var filePath = path.join(process.cwd(), uri);
343+
logger.trace('_default', filePath);
344+
345+
handleFile(filePath, request, response);
319346
}
320347
};
321348

0 commit comments

Comments
 (0)