From 5e9de9a8ab70506b05ed019030e7db7f865620d7 Mon Sep 17 00:00:00 2001 From: jonsu Date: Fri, 16 Jan 2015 14:20:01 -0800 Subject: [PATCH 1/2] Adding browser context id and updating logging params --- lib/controller.js | 10 +++++----- lib/filter.js | 4 ++-- lib/logger.js | 4 ++-- lib/minor.js | 6 +++--- lib/router.js | 14 ++++++++------ 5 files changed, 20 insertions(+), 18 deletions(-) diff --git a/lib/controller.js b/lib/controller.js index 65ed201..614d569 100644 --- a/lib/controller.js +++ b/lib/controller.js @@ -199,13 +199,13 @@ _.extend(Controller.prototype, events.EventEmitter.prototype, { }); response.render(templateName, { layout : templateValues.layout }, function (error, result) { - Logger.debug(request, request.method + ' ' + request.url + ' DONE'); + Logger.debug(request.method + ' ' + request.url + ' DONE', request); Logger.info( - request, 'Request for ' + request.minorjs.controller.name + '#' + request.minorjs.controller.action + ' done in ' + - (Date.now() - request.minorjs.start) + 'ms' + (Date.now() - request.minorjs.start) + 'ms', + request ); if (error) { @@ -243,7 +243,7 @@ _.extend(Controller.prototype, events.EventEmitter.prototype, { fullError = this._getFullError(request, response, error, incidentId), userError; - Logger.error(request, fullError); + Logger.error(fullError, request); if (request.xhr) { this._handleXhrError(request, response, error); @@ -296,7 +296,7 @@ _.extend(Controller.prototype, events.EventEmitter.prototype, { var incidentId = Indentifier.generate(), fullError = this._getFullError(request, response, error, incidentId), userError = this._getUserError(request, response, error, incidentId); - Logger.error(request, 'Could not render error page. ' + fullError); + Logger.error('Could not render error page. ' + fullError, request); response.send(userError); } else { this._handleError(request, response, error); diff --git a/lib/filter.js b/lib/filter.js index 1733d91..60838db 100644 --- a/lib/filter.js +++ b/lib/filter.js @@ -97,11 +97,11 @@ var Filter = { var result; try { - Logger.debug(request, "Running the " + self.filters[filter].moduleName + " filter"); + Logger.debug("Running the " + self.filters[filter].moduleName + " filter", request); result = self.filters[filter].process(request, response, next); return Q.isPromise(result) ? result : Q(result); } catch (e) { - Logger.debug(request, "Rejected " + self.filters[filter].moduleName + " filter"); + Logger.debug("Rejected " + self.filters[filter].moduleName + " filter", request); return Q.reject(e); } }; diff --git a/lib/logger.js b/lib/logger.js index bff9de6..c38aa70 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -57,11 +57,11 @@ var Logger = { * * Output a debug log of the number of milliseconds it took to complete a task. **/ - profile : function (name, start, end) { + profile : function (name, start, end, contextId) { if (typeof end === 'undefined') { end = Date.now(); } - this._log('debug', null, 'Performance: ' + name + ' took ' + (end - start) + 'ms'); + this._log('debug', 'Performance: ' + name + ' took ' + (end - start) + 'ms', null, contextId); }, ////////////////////////////////////////////////////////////////////////// diff --git a/lib/minor.js b/lib/minor.js index 880dcf4..362df8a 100644 --- a/lib/minor.js +++ b/lib/minor.js @@ -111,7 +111,7 @@ _.extend(Minor.prototype, { Logger.profile('Load MinorJS', self.start); - Logger.info(null, "MinorJS HTTP server listening on port " + port); + Logger.info("MinorJS HTTP server listening on port " + port); }) .fail(function (error) { console.error('Error loading controllers and registering routes.\n\n', error.stack); @@ -277,7 +277,7 @@ _.extend(Minor.prototype, { process.on('uncaughtException', function handleException (error) { console.log(error.stack) - Logger.error(null, error.stack); + Logger.error(error.stack); if (Environment.isWorker()) { cluster.worker.disconnect(); @@ -287,7 +287,7 @@ _.extend(Minor.prototype, { }); this.app.on('error', function handleError (error) { - Logger.error(null, error.stack); + Logger.error(error.stack); }); }, diff --git a/lib/router.js b/lib/router.js index d15751e..3e04ff5 100644 --- a/lib/router.js +++ b/lib/router.js @@ -26,7 +26,8 @@ var path = require('path'), Filter = require('./filter'), Environment = require('./environment'), Config = require('./config'), - Indentifier = require('./identifier'); + Indentifier = require('./identifier'), + uuid = require('node-uuid'); /** * Module for loading controllers and wiring up routes. @@ -294,10 +295,11 @@ var Router = { parts : controllerParts }, start : startTime, - requestToken : Indentifier.generate() + requestToken : Indentifier.generate(), + browserId : request.get('Browser-Context-Id') ? request.get('Browser-Context-Id') : 'browser.' + uuid.v4().replace(/-/g, '') }; - Logger.info(request, 'Request for ' + controllerName + '#' + route.handler); + Logger.info('Request for ' + controllerName + '#' + route.handler, request); Filter.run(filters, request, response, next) .then(function runController (success) { @@ -445,11 +447,11 @@ var Router = { controller.emit('request-started', request); Logger.debug( - request, request.method + ' ' + request.url + ' START. ' + 'PARAMS: ' + JSON.stringify(request.params) + ', ' + 'BODY: ' + JSON.stringify(request.body) + ', ' + - 'QUERY: ' + JSON.stringify(request.query) + 'QUERY: ' + JSON.stringify(request.query), + request ); if (Environment.isDevelopment()) { @@ -473,7 +475,7 @@ var Router = { try { Controller = require(controllerPath); } catch (error) { - Logger.error(null, "Error while loading controller '" + controllerPath + "': " + error.stack); + Logger.error("Error while loading controller '" + controllerPath + "': " + error.stack); if (Environment.isWorker()) { process.emit('message', 'shutdown'); From d96c9ec76a46bb6e2ace82dc09164cc5c2384126 Mon Sep 17 00:00:00 2001 From: jonsu Date: Fri, 16 Jan 2015 16:01:27 -0800 Subject: [PATCH 2/2] Updating tests for browser id and logging changes --- lib/router.js | 2 -- test/unit/lib/logger_test.js | 2 +- test/unit/lib/router_test.js | 69 ++++++++++++++++++++++++++++++++++-- 3 files changed, 67 insertions(+), 6 deletions(-) diff --git a/lib/router.js b/lib/router.js index 3e04ff5..27cfa25 100644 --- a/lib/router.js +++ b/lib/router.js @@ -286,7 +286,6 @@ var Router = { page = this._getPage(request), controllerParts = this._parseControllerName(request, url), controllerName = this._getControllerName(controllerParts); - request.minorjs = { page : page, controller : { @@ -298,7 +297,6 @@ var Router = { requestToken : Indentifier.generate(), browserId : request.get('Browser-Context-Id') ? request.get('Browser-Context-Id') : 'browser.' + uuid.v4().replace(/-/g, '') }; - Logger.info('Request for ' + controllerName + '#' + route.handler, request); Filter.run(filters, request, response, next) diff --git a/test/unit/lib/logger_test.js b/test/unit/lib/logger_test.js index afe9a57..e10adc2 100644 --- a/test/unit/lib/logger_test.js +++ b/test/unit/lib/logger_test.js @@ -66,7 +66,7 @@ describe('lib/logger.js', function () { start = 12345; Module = require('../../../lib/logger'); - Module._log = sinon.spy(function (level, request, message) { + Module._log = sinon.spy(function (level, message, request) { level.should.eql('debug'); message.should.match(/Performance: some name took [0-9]*ms/); }); diff --git a/test/unit/lib/router_test.js b/test/unit/lib/router_test.js index 51c09b2..8c10783 100644 --- a/test/unit/lib/router_test.js +++ b/test/unit/lib/router_test.js @@ -295,8 +295,10 @@ describe('lib/router.js', function () { url : 'some url', route : { path : 'some path' - } + }, + get : sinon.spy() }, + response = {}, next = {}, Filter = { @@ -328,7 +330,6 @@ describe('lib/router.js', function () { done(); }); - Module._handleRequest(url, route, startTime, controller, request, response, next); }); @@ -350,7 +351,8 @@ describe('lib/router.js', function () { url : 'some url', route : { path : 'some path' - } + }, + get : sinon.spy() }, response = {}, next = {}, @@ -386,6 +388,67 @@ describe('lib/router.js', function () { Module._handleRequest(url, route, startTime, controller, request, response, next); }); + + it('should handle browser id generation', function (done) { + var url = 'some/url', + filters = [ 'some filters' ], + controller = { + getFilters : sinon.spy(function () { + return filters; + }) + }, + route = { + handler : 'some handler' + }, + req_w_id = { + url : 'some url', + route : { + path : 'some path' + }, + 'Browser-Context-Id' : 'some browser id', + get : sinon.spy(function(key){ + return this[key]; + }) + }, + req_no_id = { + url : 'some url', + route : { + path : 'some path' + }, + get : sinon.spy(function(key){ + return this[key]; + }) + }, + + response = {}, + next = {}, + Filter = { + run : sinon.spy(function () { + return Q(true); + }) + }, + Logger = { + info : sinon.spy() + }, + startTime = Date.now(); + + Backhoe.mock(require.resolve('../../../lib/logger'), Logger); + + Module = require('../../../lib/router'); + + Module._runController = sinon.spy(); + Module._handleError = sinon.spy(); + + Module._handleRequest(url, route, startTime, controller, req_w_id, response, next); + req_w_id.get.calledWith('Browser-Context-Id'); + req_w_id.minorjs.browserId.should.eql('some browser id'); + + Module._handleRequest(url, route, startTime, controller, req_no_id, response, next); + req_no_id.get.calledWith('Browser-Context-Id'); + req_no_id.minorjs.browserId.indexOf('browser').should.eql(0); + + done(); + }); }); describe('_handleDevelopmentRequest', function () {