diff --git a/lib/application.js b/lib/application.js index 838b882aaae..e4467da3727 100644 --- a/lib/application.js +++ b/lib/application.js @@ -23,7 +23,9 @@ var compileQueryParser = require('./utils').compileQueryParser; var compileTrust = require('./utils').compileTrust; var resolve = require('node:path').resolve; var once = require('once') +var onFinished = require('on-finished'); var Router = require('router'); +var channels = require('./diagnostics'); /** * Module variables. @@ -150,12 +152,39 @@ app.defaultConfiguration = function defaultConfiguration() { */ app.handle = function handle(req, res, callback) { + var startTime = process.hrtime(); + + if (channels.requestStart.hasSubscribers) { + channels.requestStart.publish({ req: req, res: res }); + } + // final handler var done = callback || finalhandler(req, res, { env: this.get('env'), onerror: logerror.bind(this) }); + // wrap done to publish error + var next = function (err) { + if (err && channels.requestError.hasSubscribers) { + channels.requestError.publish({ req: req, res: res, error: err }); + } + done(err); + }; + + onFinished(res, function (err) { + var diff = process.hrtime(startTime); + var duration = diff[0] * 1e3 + diff[1] * 1e-6; + + if (err && channels.requestError.hasSubscribers) { + channels.requestError.publish({ req: req, res: res, error: err }); + } + + if (channels.requestEnd.hasSubscribers) { + channels.requestEnd.publish({ req: req, res: res, duration: duration }); + } + }); + // set powered by header if (this.enabled('x-powered-by')) { res.setHeader('X-Powered-By', 'Express'); @@ -174,7 +203,7 @@ app.handle = function handle(req, res, callback) { res.locals = Object.create(null); } - this.router.handle(req, res, done); + this.router.handle(req, res, next); }; /** @@ -219,7 +248,7 @@ app.use = function use(fn) { fns.forEach(function (fn) { // non-express app if (!fn || !fn.handle || !fn.set) { - return router.use(path, fn); + return router.use(path, wrapMiddleware(fn)); } debug('.use app under %s', path); @@ -328,7 +357,7 @@ app.param = function param(name, fn) { return this; } - this.router.param(name, fn); + this.router.param(name, wrapMiddleware(fn, true)); return this; }; @@ -476,7 +505,8 @@ methods.forEach(function (method) { } var route = this.route(path); - route[method].apply(route, slice.call(arguments, 1)); + var args = slice.call(arguments, 1).map(wrapMiddleware); + route[method].apply(route, args); return this; }; }); @@ -493,7 +523,7 @@ methods.forEach(function (method) { app.all = function all(path) { var route = this.route(path); - var args = slice.call(arguments, 1); + var args = slice.call(arguments, 1).map(wrapMiddleware); for (var i = 0; i < methods.length; i++) { route[methods[i]].apply(route, args); @@ -629,3 +659,105 @@ function tryRender(view, options, callback) { callback(err); } } + +/** + * Wrap a middleware function with diagnostic hooks. + * @param {Function} fn + * @return {Function} + * @private + */ +function wrapMiddleware(fn, isParam) { + if (typeof fn !== 'function') return fn; + + var name = fn.name || ''; + var isErrorMiddleware = !isParam && fn.length === 4; + + var wrapped; + if (isErrorMiddleware) { + wrapped = function (err, req, res, next) { + if (!channels.middlewareStart.hasSubscribers && + !channels.middlewareEnd.hasSubscribers && + !channels.middlewareError.hasSubscribers) { + return fn(err, req, res, next); + } + + var startTime = process.hrtime(); + if (channels.middlewareStart.hasSubscribers) { + channels.middlewareStart.publish({ req: req, res: res, name: name }); + } + + if (req.route && channels.routeMatch.hasSubscribers && req._lastPublishedRoute !== req.route) { + channels.routeMatch.publish({ req: req, route: req.route }); + req._lastPublishedRoute = req.route; + } + + var wrappedNext = function (e) { + var diff = process.hrtime(startTime); + var duration = diff[0] * 1e3 + diff[1] * 1e-6; + + if (e && channels.middlewareError.hasSubscribers) { + channels.middlewareError.publish({ req: req, res: res, name: name, error: e }); + } + + if (channels.middlewareEnd.hasSubscribers) { + channels.middlewareEnd.publish({ req: req, res: res, name: name, duration: duration }); + } + + next(e); + }; + + req.next = wrappedNext; + fn(err, req, res, wrappedNext); + }; + } else { + wrapped = function (req, res, next) { // eslint-disable-line no-unused-vars + if (!channels.middlewareStart.hasSubscribers && + !channels.middlewareEnd.hasSubscribers && + !channels.middlewareError.hasSubscribers) { + return fn.apply(this, arguments); + } + + var args = slice.call(arguments); + var startTime = process.hrtime(); + if (channels.middlewareStart.hasSubscribers) { + channels.middlewareStart.publish({ req: req, res: res, name: name }); + } + + if (req.route && channels.routeMatch.hasSubscribers && req._lastPublishedRoute !== req.route) { + channels.routeMatch.publish({ req: req, route: req.route }); + req._lastPublishedRoute = req.route; + } + + var originalNext = args[2]; + var wrappedNext = function (e) { + var diff = process.hrtime(startTime); + var duration = diff[0] * 1e3 + diff[1] * 1e-6; + + if (e && channels.middlewareError.hasSubscribers) { + channels.middlewareError.publish({ req: req, res: res, name: name, error: e }); + } + + if (channels.middlewareEnd.hasSubscribers) { + channels.middlewareEnd.publish({ req: req, res: res, name: name, duration: duration }); + } + + originalNext(e); + }; + + args[2] = wrappedNext; + req.next = wrappedNext; + + fn.apply(this, args); + }; + } + + if (fn.length > 0) { + try { + Object.defineProperty(wrapped, 'length', { value: fn.length, configurable: true }); + } catch (e) { + // ignore + } + } + + return wrapped; +} diff --git a/lib/diagnostics.js b/lib/diagnostics.js new file mode 100644 index 00000000000..419fe763ab3 --- /dev/null +++ b/lib/diagnostics.js @@ -0,0 +1,23 @@ +'use strict'; + +/** + * Module dependencies. + * @private + */ + +var diagnostics_channel = require('node:diagnostics_channel'); + +/** + * Module exports. + * @public + */ + +module.exports = { + requestStart: diagnostics_channel.channel('express.request.start'), + requestEnd: diagnostics_channel.channel('express.request.end'), + requestError: diagnostics_channel.channel('express.request.error'), + middlewareStart: diagnostics_channel.channel('express.middleware.start'), + middlewareEnd: diagnostics_channel.channel('express.middleware.end'), + middlewareError: diagnostics_channel.channel('express.middleware.error'), + routeMatch: diagnostics_channel.channel('express.route.match') +}; diff --git a/test/diagnostics.js b/test/diagnostics.js new file mode 100644 index 00000000000..0615edbfbfc --- /dev/null +++ b/test/diagnostics.js @@ -0,0 +1,135 @@ +'use strict'; + +var express = require('../'); +var request = require('supertest'); +var assert = require('node:assert'); +var dc = require('node:diagnostics_channel'); + +describe('diagnostics', function () { + it('should publish express.request.start', function (done) { + var app = express(); + var events = []; + + dc.subscribe('express.request.start', function (message) { + events.push(message); + }); + + app.get('/', function (req, res) { + res.send('ok'); + }); + + request(app) + .get('/') + .expect(200, function (err) { + if (err) return done(err); + assert.strictEqual(events.length, 1); + assert.ok(events[0].req); + assert.ok(events[0].res); + done(); + }); + }); + + it('should publish express.request.end', function (done) { + var app = express(); + var events = []; + + dc.subscribe('express.request.end', function (message) { + events.push(message); + }); + + app.get('/', function (req, res) { + res.send('ok'); + }); + + request(app) + .get('/') + .expect(200, function (err) { + if (err) return done(err); + // Wait a bit for on-finished to fire + setTimeout(function () { + assert.strictEqual(events.length, 1); + assert.ok(events[0].req); + assert.ok(events[0].res); + assert.strictEqual(typeof events[0].duration, 'number'); + done(); + }, 10); + }); + }); + + it('should publish express.request.error', function (done) { + var app = express(); + var events = []; + + dc.subscribe('express.request.error', function (message) { + events.push(message); + }); + + app.get('/', function (req, res, next) { + next(new Error('boom')); + }); + + request(app) + .get('/') + .expect(500, function (err) { + if (err) return done(err); + assert.strictEqual(events.length, 1); + assert.strictEqual(events[0].error.message, 'boom'); + done(); + }); + }); + + it('should publish express.middleware events', function (done) { + var app = express(); + var startEvents = []; + var endEvents = []; + + dc.subscribe('express.middleware.start', function (message) { + startEvents.push(message); + }); + + dc.subscribe('express.middleware.end', function (message) { + endEvents.push(message); + }); + + function myMiddleware(req, res, next) { + next(); + } + + app.use(myMiddleware); + + app.get('/', function (req, res) { + res.send('ok'); + }); + + request(app) + .get('/') + .expect(200, function (err) { + if (err) return done(err); + assert.ok(startEvents.some(e => e.name === 'myMiddleware')); + assert.ok(endEvents.some(e => e.name === 'myMiddleware')); + done(); + }); + }); + + it('should publish express.route.match', function (done) { + var app = express(); + var events = []; + + dc.subscribe('express.route.match', function (message) { + events.push(message); + }); + + app.get('/user/:id', function (req, res) { + res.send('ok'); + }); + + request(app) + .get('/user/123') + .expect(200, function (err) { + if (err) return done(err); + assert.strictEqual(events.length, 1); + assert.strictEqual(events[0].route.path, '/user/:id'); + done(); + }); + }); +});