From 7f2afee418e1f274e7c2ffd84811125d9a09b094 Mon Sep 17 00:00:00 2001 From: Vinicius Baggio Fuentes Date: Thu, 18 Jul 2013 17:51:05 -0700 Subject: [PATCH 1/4] Creating a default request logger --- package.json | 3 +- src/RequestMessage.js | 140 ++++++++++++++++++ src/matador.js | 24 +++ tests/functional/app/config/routes.js | 5 + .../app/controllers/HomeController.js | 16 ++ tests/functional/logger_test.js | 34 +++++ tests/support/functional.js | 101 +++++++++++++ 7 files changed, 322 insertions(+), 1 deletion(-) create mode 100644 src/RequestMessage.js create mode 100644 tests/functional/app/config/routes.js create mode 100644 tests/functional/app/controllers/HomeController.js create mode 100644 tests/functional/logger_test.js create mode 100644 tests/support/functional.js diff --git a/package.json b/package.json index 9403661..2b49e8b 100644 --- a/package.json +++ b/package.json @@ -27,7 +27,8 @@ "colors": "*", "optimist": "*", "soynode": "~0.2.0", - "nodeunit": "~0.8.0" + "nodeunit": "~0.8.0", + "useragent": "~2.0.6" }, "devDependencies": { "jshint": "2.0.1", diff --git a/src/RequestMessage.js b/src/RequestMessage.js new file mode 100644 index 0000000..b602cf1 --- /dev/null +++ b/src/RequestMessage.js @@ -0,0 +1,140 @@ +// Copyright The Obvious Corporation 2013 + +/** + * @fileoverview + * A request message is a message builder for incoming requests. + * By default, it logs the route taken, source IP address, parameters + * and response code. + * + * Example of a request message with the default factory: + * + * Thu, 18 Jul 2013 23:35:28 GMT - GET /people/29 (source 127.0.0.1) + * Parameters: {"id":"29"} + * Query: {} + * Body: {} + * Controller: People.show + * Response: 200 in 39ms (6441 bytes) + */ +var useragent = require('useragent') + +function RequestMessage() { + this._events = [] +} + +/** + * A request message factory that includes the most common + * request events for logging purposes + * @return {RequestMessage} a request message with default events + */ +RequestMessage.buildDefaultMessage = function () { + var message = new RequestMessage() + + message.addRequestEvent('Parameters', function (req, res) { + return JSON.stringify(req.params) + }) + + message.addRequestEvent('Query', function (req, res) { + return JSON.stringify(req.query) + }) + + message.addRequestEvent('Controller', function (req, res) { + if (req.target) { + return req.target.controllerName + '.' + req.target.methodName + } + }) + + message.addRequestEvent('Response', function (req, res) { + var bodySize = ((res && res.getHeader('content-length')) || 'unknown') + ' bytes' + , responseTime = this._finishTime - this._startTime + + return [ + res.statusCode, + 'in', + responseTime + 'ms', + '(' + bodySize + ')' + ].join(' ') + }) + + return message +} + +/** + * Add a new event to the request. It takes a name and a builder function. + * The builder function receives the request and the response objects + * for the function to inspect and build appropriate message. + * See .buildDefaultMessage for examples + * @param {string} eventName the name of the event to be logged. + * @param {function} builder function called to build a message for the event + * eventName + */ +RequestMessage.prototype.addRequestEvent = function(eventName, builder) { + this._events.push({name: eventName, builder: builder}) +} + +/** + * Builds a string using the registered request events + * @param {http.Request} req request + * @param {http.Response} res response + * @return {string} the request message + */ +RequestMessage.prototype.buildMessage = function (req, res) { + var messages = [this._buildHeader(req)] + , events = this._events.map(function (event) { + return this._buildEventMessage(event, req, res) + }.bind(this)) + + events = events.filter(function (message) { + return message && message.length > 0 + }) + + return messages.concat(events).join('\n') + '\n' +} + +/** + * Called when the request starts, used for calculating + * request duration. + */ +RequestMessage.prototype.requestStart = function() { + this._startTime = Date.now() +} + +/** + * Called when the request ends, used for calculating + * request duration. + */ +RequestMessage.prototype.requestEnd = function() { + this._finishTime = Date.now() +} + +/** + * Builds the default header for request message, including origin, + * uri and time. + * @private + */ +RequestMessage.prototype._buildHeader = function (req) { + var method = req.method + , uri = req.originalUrl + , remoteAddress = req.headers['X-Forwarded-For'] || req.connection.remoteAddress + + return [ + new Date().toUTCString(), + '-', + method, + uri, + '(source ' + remoteAddress + ')' + ].join(' ') +} + +/** + * Goes through all the registered events and build its message. + * @private + */ +RequestMessage.prototype._buildEventMessage = function (event, req, res) { + var message = event.builder.bind(this)(req, res) + if (message) { + return ' ' + event.name + ': ' + message + } +} + +module.exports = RequestMessage + diff --git a/src/matador.js b/src/matador.js index 65e4761..198b0d7 100644 --- a/src/matador.js +++ b/src/matador.js @@ -10,6 +10,7 @@ var fs = require('fs') , FileLoader = require('./FileLoader') , ClassLoader = require('./ClassLoader') , PathMatcher = require('./pathMatcher') + , RequestMessage = require('./RequestMessage') , isDirectory = fsutils.isDirectory // DEPRECATED: Some old apps rely on argv being parsed by @@ -423,6 +424,28 @@ module.exports.createApp = function (baseDir, configuration, options) { objCache[paths.MODELS][name + filenameSuffixes.MODELS] = instance } + app.requestLogger = function (requestMessage, logger) { + return function (req, res, next) { + requestMessage.requestStart() + + var end = res.end + res.end = function (chunk, encoding) { + end.call(res, chunk, encoding) + requestMessage.requestEnd() + + if (!/\.(jpg|png|less|js|soy|otf|ico)$/.test(req.originalUrl) && !/plovr\/proxy/.test(req.originalUrl)) { + logger.info(requestMessage.buildMessage(req, res)) + } + } + next() + } + } + + app.developmentRequestLogger = function () { + var message = RequestMessage.buildDefaultMessage() + return app.requestLogger(message, console) + } + app.boot = function () { // Register the matador cache helper. app.registerHelper('Cache', CacheHelper) @@ -444,6 +467,7 @@ module.exports.createApp = function (baseDir, configuration, options) { app.mount() app.configure('development', function () { + app.use(app.developmentRequestLogger()) app.use(matador.errorHandler({ dumpExceptions: true, showStack: true })) app.set('soy options', { eraseTemporaryFiles: true diff --git a/tests/functional/app/config/routes.js b/tests/functional/app/config/routes.js new file mode 100644 index 0000000..87a3758 --- /dev/null +++ b/tests/functional/app/config/routes.js @@ -0,0 +1,5 @@ +module.exports = function (app) { + return { + '/': 'Home.index' + } +} diff --git a/tests/functional/app/controllers/HomeController.js b/tests/functional/app/controllers/HomeController.js new file mode 100644 index 0000000..51beb68 --- /dev/null +++ b/tests/functional/app/controllers/HomeController.js @@ -0,0 +1,16 @@ +var util = require('util') + +module.exports = function (app, config) { + function HomeController() { + app.controllers.Base.call(this) + } + + util.inherits(HomeController, app.controllers.Base) + + HomeController.prototype.index = function(req, res) { + return res.send('hello') + } + + + return HomeController +} diff --git a/tests/functional/logger_test.js b/tests/functional/logger_test.js new file mode 100644 index 0000000..37f5959 --- /dev/null +++ b/tests/functional/logger_test.js @@ -0,0 +1,34 @@ +// Copyright The Obvious Corporation 2013 + +require('../support/functional') + +var matador = require('../../src/matador') + , RequestMessage = require('../../src/RequestMessage') + +exports.testLogsRequest = function (test) { + var app = matador.createApp(__dirname, {}, {}) + , requestMessage = RequestMessage.buildDefaultMessage() + , messages = [] + + var fakeLogger = { + info: function (message) { + messages.push(message) + } + } + + app.use(app.requestLogger(requestMessage, fakeLogger)) + app.boot() + + app.request() + .get('/?hello=world') + .end(function (res) { + var messageLines = messages[0].split('\n') + test.ok(messageLines[0].indexOf('- GET /?hello=world (source 127.0.0.1)') >= 0, 'method not included in log') + test.ok(messageLines[1].indexOf('Parameters: {}') >= 0, 'parameters not included in log') + test.ok(messageLines[2].indexOf('Query: {"hello":"world"}') >= 0, 'query strings not included in log') + test.ok(messageLines[3].indexOf('Controller: Home.index') >= 0, 'controller#action not included in log') + test.ok(messageLines[4].match(/Response: 200 in \d+ms \(5 bytes\)/), 'response code not included in log') + + test.done() + }) +} diff --git a/tests/support/functional.js b/tests/support/functional.js new file mode 100644 index 0000000..c1146be --- /dev/null +++ b/tests/support/functional.js @@ -0,0 +1,101 @@ +/** + * Connect js' testing support: + * https://raw.github.com/senchalabs/connect/master/test/support/http.js + * + * PS(vinny): I have changed the request's end() to actually stop + * the server so no sockets are left open after a test. + */ + +var EventEmitter = require('events').EventEmitter + , methods = ['get', 'post', 'put', 'delete', 'head'] + , connect = require('../../') + , http = require('http') + +module.exports = request + +connect.proto.request = function(){ + return request(this) +} + +function request(app) { + return new Request(app) +} + +function Request(app) { + var self = this + this.data = [] + this.header = {} + this.app = app + if (!this.server) { + this.server = http.Server(app) + this.server.listen(0, function(){ + self.addr = self.server.address() + self.listening = true + }) + } +} + +/** + * Inherit from `EventEmitter.prototype`. + */ + +Request.prototype.__proto__ = EventEmitter.prototype + +methods.forEach(function(method){ + Request.prototype[method] = function(path){ + return this.request(method, path) + } +}) + +Request.prototype.request = function(method, path){ + this.method = method + this.path = path + return this +} + +Request.prototype.set = function(field, val){ + this.header[field] = val + return this +} + +Request.prototype.write = function(data){ + this.data.push(data) + return this +} + +Request.prototype.end = function(fn){ + var self = this + + if (this.listening) { + var req = http.request({ + method: this.method + , port: this.addr.port + , host: this.addr.address + , path: this.path + , headers: this.header + }) + + this.data.forEach(function(chunk){ + req.write(chunk) + }) + + req.on('response', function(res){ + var buf = '' + res.setEncoding('utf8') + res.on('data', function(chunk){ buf += chunk }) + res.on('end', function(){ + res.body = buf + fn(res) + self.server.close() + }) + }) + + req.end() + } else { + this.server.on('listening', function(){ + self.end(fn) + }) + } + + return this +} From 4687b010e9c5dbf0fa799dac4890c32bbb4df9eb Mon Sep 17 00:00:00 2001 From: Vinicius Baggio Fuentes Date: Thu, 18 Jul 2013 19:14:09 -0700 Subject: [PATCH 2/4] Request Messages are built every request instead of once per app boot --- src/matador.js | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/matador.js b/src/matador.js index 198b0d7..87f1e4c 100644 --- a/src/matador.js +++ b/src/matador.js @@ -442,8 +442,10 @@ module.exports.createApp = function (baseDir, configuration, options) { } app.developmentRequestLogger = function () { - var message = RequestMessage.buildDefaultMessage() - return app.requestLogger(message, console) + return function (req, res, next) { + var message = RequestMessage.buildDefaultMessage() + app.requestLogger(message, console)(req, res, next) + } } app.boot = function () { From ac40f83be896b316d29c9ad813df01ac13ddcb65 Mon Sep 17 00:00:00 2001 From: Vinicius Baggio Fuentes Date: Thu, 18 Jul 2013 19:19:43 -0700 Subject: [PATCH 3/4] Renaming request events to request message sections --- src/RequestMessage.js | 53 ++++++++++++++++++++----------------------- 1 file changed, 25 insertions(+), 28 deletions(-) diff --git a/src/RequestMessage.js b/src/RequestMessage.js index b602cf1..a2bae1d 100644 --- a/src/RequestMessage.js +++ b/src/RequestMessage.js @@ -11,39 +11,38 @@ * Thu, 18 Jul 2013 23:35:28 GMT - GET /people/29 (source 127.0.0.1) * Parameters: {"id":"29"} * Query: {} - * Body: {} * Controller: People.show * Response: 200 in 39ms (6441 bytes) */ var useragent = require('useragent') function RequestMessage() { - this._events = [] + this._sections = [] } /** * A request message factory that includes the most common - * request events for logging purposes - * @return {RequestMessage} a request message with default events + * request sections for logging purposes + * @return {RequestMessage} a request message with default sections */ RequestMessage.buildDefaultMessage = function () { var message = new RequestMessage() - message.addRequestEvent('Parameters', function (req, res) { + message.addMessageSection('Parameters', function (req, res) { return JSON.stringify(req.params) }) - message.addRequestEvent('Query', function (req, res) { + message.addMessageSection('Query', function (req, res) { return JSON.stringify(req.query) }) - message.addRequestEvent('Controller', function (req, res) { + message.addMessageSection('Controller', function (req, res) { if (req.target) { return req.target.controllerName + '.' + req.target.methodName } }) - message.addRequestEvent('Response', function (req, res) { + message.addMessageSection('Response', function (req, res) { var bodySize = ((res && res.getHeader('content-length')) || 'unknown') + ' bytes' , responseTime = this._finishTime - this._startTime @@ -58,36 +57,35 @@ RequestMessage.buildDefaultMessage = function () { return message } -/** - * Add a new event to the request. It takes a name and a builder function. - * The builder function receives the request and the response objects - * for the function to inspect and build appropriate message. - * See .buildDefaultMessage for examples - * @param {string} eventName the name of the event to be logged. - * @param {function} builder function called to build a message for the event - * eventName +/** Add a new section to the request message. It takes a name and a builder + * function. The builder function receives the request and the response + * objects for the function to inspect and build appropriate message. See + * .buildDefaultMessage for examples + * @param {string} section the name of the section to be logged. + * @param {function} builder function called to build + * a message for the section sectionName */ -RequestMessage.prototype.addRequestEvent = function(eventName, builder) { - this._events.push({name: eventName, builder: builder}) +RequestMessage.prototype.addMessageSection = function(sectionName, messageBuilder) { + this._sections.push({name: sectionName, builder: messageBuilder}) } /** - * Builds a string using the registered request events + * Builds a string using the registered request message sections * @param {http.Request} req request * @param {http.Response} res response * @return {string} the request message */ RequestMessage.prototype.buildMessage = function (req, res) { var messages = [this._buildHeader(req)] - , events = this._events.map(function (event) { - return this._buildEventMessage(event, req, res) + , sections = this._sections.map(function (section) { + return this._buildSectionMessage(section, req, res) }.bind(this)) - events = events.filter(function (message) { + sections = sections.filter(function (message) { return message && message.length > 0 }) - return messages.concat(events).join('\n') + '\n' + return messages.concat(sections).join('\n') + '\n' } /** @@ -126,15 +124,14 @@ RequestMessage.prototype._buildHeader = function (req) { } /** - * Goes through all the registered events and build its message. + * Goes through all the registered sections and build its message. * @private */ -RequestMessage.prototype._buildEventMessage = function (event, req, res) { - var message = event.builder.bind(this)(req, res) +RequestMessage.prototype._buildSectionMessage = function (section, req, res) { + var message = section.builder.bind(this)(req, res) if (message) { - return ' ' + event.name + ': ' + message + return ' ' + section.name + ': ' + message } } module.exports = RequestMessage - From 5fcf566b7d38ea205b416845209e6b0e3dbccf76 Mon Sep 17 00:00:00 2001 From: Vinicius Baggio Fuentes Date: Thu, 18 Jul 2013 19:32:01 -0700 Subject: [PATCH 4/4] Moving sections to their own methods and improving documentation --- src/RequestMessage.js | 45 +++++++++++++++++++++++++++++++++++++------ src/matador.js | 8 ++++++++ 2 files changed, 47 insertions(+), 6 deletions(-) diff --git a/src/RequestMessage.js b/src/RequestMessage.js index a2bae1d..f084749 100644 --- a/src/RequestMessage.js +++ b/src/RequestMessage.js @@ -28,21 +28,56 @@ function RequestMessage() { RequestMessage.buildDefaultMessage = function () { var message = new RequestMessage() - message.addMessageSection('Parameters', function (req, res) { + message.addParameterSection() + message.addQuerySection() + message.addControllerSection() + message.addResponseSection() + + return message +} + +/** + * Adds a section to the request message that logs the URI + * parameters. + */ +RequestMessage.prototype.addParameterSection = function () { + this.addMessageSection('Parameters', function (req, res) { return JSON.stringify(req.params) }) +} - message.addMessageSection('Query', function (req, res) { +/** + * Adds a section to the request message that logs the query string + * parameters. + */ +RequestMessage.prototype.addQuerySection = function() { + this.addMessageSection('Query', function (req, res) { return JSON.stringify(req.query) }) +} - message.addMessageSection('Controller', function (req, res) { +/** + * Adds a section to the request message that logs the controller + * and action that handled the request. + */ +RequestMessage.prototype.addControllerSection = function() { + this.addMessageSection('Controller', function (req, res) { if (req.target) { return req.target.controllerName + '.' + req.target.methodName } }) +} - message.addMessageSection('Response', function (req, res) { +/** + * Adds a section to the request message that logs response: + * - status code + * - response time + * - body size + * + * E.g.: "Response: 200 in 39ms (6441 bytes)" + */ +RequestMessage.prototype.addResponseSection = function() { + this.addMessageSection('Response', function (req, res) { var bodySize = ((res && res.getHeader('content-length')) || 'unknown') + ' bytes' , responseTime = this._finishTime - this._startTime @@ -53,8 +88,6 @@ RequestMessage.buildDefaultMessage = function () { '(' + bodySize + ')' ].join(' ') }) - - return message } /** Add a new section to the request message. It takes a name and a builder diff --git a/src/matador.js b/src/matador.js index 87f1e4c..fd5d424 100644 --- a/src/matador.js +++ b/src/matador.js @@ -424,6 +424,10 @@ module.exports.createApp = function (baseDir, configuration, options) { objCache[paths.MODELS][name + filenameSuffixes.MODELS] = instance } + /** + * Middleware that calls a request logger every request. Useful + * for displaying basic data about a request. + */ app.requestLogger = function (requestMessage, logger) { return function (req, res, next) { requestMessage.requestStart() @@ -441,6 +445,10 @@ module.exports.createApp = function (baseDir, configuration, options) { } } + /** + * Builds a request logger for development purposes: it logs predefined + * data onto the console. + */ app.developmentRequestLogger = function () { return function (req, res, next) { var message = RequestMessage.buildDefaultMessage()