feat: add diagnostics_channel support for request lifecycle, middleware, and route events

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 || '<anonymous>';
+  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;
+}

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')
+};

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();
+            });
+  });
+});