Add tracing capabilities to Express

examples/trace/index.js

@@ -0,0 +1,53 @@
+var debug = require('debug')('trace-example');
+var express = require('../../');
+
+var app = express();
+
+// Add a middleware that runs trace function.
+app.use(function(req, res, next){
+  res.start = Date.now()
+  res.id = random();
+  res.trace('start', new Date());
+  next();
+});
+
+// Add another middleware that runs trace after an asynchronous call.
+app.use(function(req, res, next){
+  res.trace('wait:before');
+  setTimeout(function () {
+    res.trace('wait:after');
+    next();
+  }, Math.random() * 100);
+})
+
+// Add a route to show request traces.
+app.get('/', function(req, res, next){
+  res.trace('user.id', random());
+  res.trace('some.event', random(), random());
+  res.trace('another.event', random(), random());
+  res.set('X-Response-Time', (Date.now() - res.start) + 'ms');
+  res.send('Hello world!');
+  next();
+});
+
+// Add an after request processing middleware that runs trace.
+app.use(function(req, res, next){
+  res.trace('finish');
+});
+
+// Configure tracer.
+app.instrument(function(options){
+  debug(options.res.id, options.event, options.args.join(' '));
+});
+
+// Helpers to generate random ids.
+function random(){
+  return Math.random().toString(36).slice(2);
+};
+
+
+/* istanbul ignore next */
+if (!module.parent) {
+  app.listen(3000);
+  console.log('Express started on port 3000');
+}

lib/application.js

@@ -57,6 +57,7 @@ app.init = function init() {
   this.cache = {};
   this.engines = {};
   this.settings = {};
+  this.tracers = [];
 
   this.defaultConfiguration();
 };
@@ -98,6 +99,10 @@ app.defaultConfiguration = function defaultConfiguration() {
     this.response.__proto__ = parent.response;
     this.engines.__proto__ = parent.engines;
     this.settings.__proto__ = parent.settings;
+
+    this.instrument(function callParentTracer(options) {
+      parent._callTracers(options.res, options.event, options.args);
+    });
   });
 
   // setup locals
@@ -617,6 +622,63 @@ app.listen = function listen() {
   return server.listen.apply(server, arguments);
 };
 
+/*
+ * Set a tracer at the application level. Tracer will be activated when a
+ * tracing call will be fired by a response.
+ * The tracer function takes an option object as argument with the given
+ * attributes:
+ *
+ * - app: current application
+ * - res: response that fires the tracer
+ * - req: request related to above response
+ * - event: string describing the event to trace
+ * - date: when the tracing occurs
+ * - args: allow to freely add information
+ *
+ * @param {function} The tracer to set.
+ * @return {app} for chaining.
+ * @public
+ */
+
+app.instrument = function(tracer){
+  if (tracer === undefined || typeof tracer !== 'function')
+    throw new TypeError('instrument expects a function');
+  this.tracers.push(tracer);
+  return this;
+};
+
+/*
+ * Call all tracers set on the application. Add context information:
+ * running app, request, response and date. The date is the when the tracing
+ * was fired (now).
+ *
+ * @param {Response} Response that fires the tracing event.
+ * @param {Event} The event to trace.
+ * @param {Array} Arguments to transmit to the tracker.
+ *
+ * @private
+ */
+
+app._callTracers = function(res, event, args){
+  var date = new Date();
+  var app = this;
+  var tracers = this.tracers;
+  var length = tracers.length;
+
+  var options = {
+    app: app,
+    res: res,
+    req: res.req,
+    event: event,
+    date: date,
+    args: args
+  };
+
+  for (var i = 0; i < length; i++) {
+    tracers[i](options);
+  }
+};
+
 /**
  * Log error using console.error.
  *

lib/response.js

@@ -1051,6 +1051,34 @@ function sendfile(res, file, options, callback) {
   file.pipe(res);
 }
 
+/**
+ * Run every tracers set at the application level for given events
+ * and arguments. To set a tracer on the application use the `instrument`
+ * method.
+ *
+ * @param {function} event The event to trace.
+ * @return {ServerResponse} for chaining
+ * @public
+ */
+
+res.trace = function(event) {
+  var args;
+  switch (arguments.length) {
+    case 0:
+      throw new Error('No event defined!');
+    case 1:
+      args = [];
+      break;
+    case 2:
+      args = [arguments[1]];
+      break;
+    default:
+      args = [].slice.call(arguments, 1);
+  }
+  this.app._callTracers(this, event, args);
+  return this;
+};
+
 /**
  * Stringify JSON, like JSON.stringify, but v8 optimized.
  * @private

test/app.instrument.js

@@ -0,0 +1,23 @@
+
+var express = require('../');
+
+describe('app', function(){
+  describe('.instrument(fn)', function(){
+    it('should add function to the tracer list', function(){
+      var app = express();
+      function debug (options) {
+        console.log(options.event);
+      }
+      app.instrument(debug);
+      debug.should.be.equal(app.tracers[0]);
+    });
+
+    it('should throw err if tracer is not a function', function(){
+      var app = express();
+
+      (function(){
+        app.instrument('notatracer');
+      }).should.throw('instrument expects a function');
+    });
+  })
+})

test/res.trace.js

@@ -0,0 +1,98 @@
+
+var express = require('../');
+var request = require('supertest');
+var assert = require('assert');
+
+describe('res', function(){
+  describe('.trace(event)', function(){
+    it('should call all tracers set at application level', function(done){
+      var app = express();
+
+      app.instrument(function(options){
+        assert.equal(options.app, app)
+        assert.equal(options.req.url, '/');
+        assert.equal(options.res.id, '1');
+        assert.equal(options.event, 'one:event');
+        assert.equal(options.args[0], 'info');
+      });
+
+      app.use(function(req, res, next){
+        res.id = '1';
+        res.trace('one:event', 'info');
+        next();
+      });
+
+      app.get('/', function(req, res){
+        res.send('ok');
+      });
+
+      request(app)
+        .get('/')
+        .expect(200, done);
+    })
+  })
+
+  describe('.trace(event) with parents', function(){
+    it('should call parent tracers too', function(done){
+
+      var app = express();
+      var appParent1 = express();
+      var appParent2 = express();
+
+      var parentTraces1 = [];
+      var parentTraces2 = [];
+
+      appParent1.instrument(function(options){
+        assert.equal(options.req.id, '1');
+        parentTraces1.push(options.event + ':parent1');
+      });
+
+      appParent2.instrument(function(options){
+        assert.equal(options.req.id, '1');
+        parentTraces2.push(options.event + ':parent2');
+      });
+
+      appParent1.use('/childof1', app);
+      appParent2.use('/childof2', app);
+      app.instrument(function(options){
+        assert.equal(options.event, 'one:event');
+        assert.equal(options.args[0], 'info');
+      });
+
+      app.use(function(req, res, next){
+        req.id = '1';
+        next();
+      });
+
+      app.get('/', function(req, res){
+        res.trace('one:event', 'info');
+        res.send('ok');
+      });
+
+      request(appParent1)
+        .get('/childof1')
+        .expect(200, function(err){
+        if (err) return done(err);
+
+        assert.equal(parentTraces1.length, 1);
+        assert.equal(parentTraces2.length, 1);
+        assert.equal(parentTraces1[0], 'one:event:parent1');
+        assert.equal(parentTraces2[0], 'one:event:parent2');
+
+        request(appParent2)
+          .get('/childof2')
+          .expect(200, function(err){
+          if (err) return done(err);
+
+          assert.equal(parentTraces1.length, 2);
+          assert.equal(parentTraces2.length, 2);
+          assert.equal(parentTraces1[0], 'one:event:parent1');
+          assert.equal(parentTraces2[0], 'one:event:parent2');
+          assert.equal(parentTraces1[1], 'one:event:parent1');
+          assert.equal(parentTraces2[1], 'one:event:parent2');
+          done();
+        });
+      });
+    });
+  })
+});