Handle context between two async requests

When using `req.miniprofiler` to track the miniprofiler extension, two
requests can dispute this resource where the reference will always point
to the last request.

So a scenario with async timings, the first request can endup using
`req.miniprofiler` that points to the second request extension.
(Check the tests to see a scenario simulation)

Using NodeJS "async_hooks" we can track the reference to the correct
extension for each request.

Related to: MiniProfiler#4

Author: Danilo Resende

lib/miniprofiler.js

@@ -15,6 +15,7 @@
  var url = require('url');
  var ui = require('./ui.js');
  var clientParser = require('./client-parser.js');
+ var ContinuationLocalStorage = require('asyncctx').ContinuationLocalStorage;
 
  const hostname = require('os').hostname;
 var ignoredPaths = [];
@@ -27,6 +28,7 @@ var ignoredPaths = [];
   RedisStorage: require('./storages/redis.js')
 };
 
+var cls = new ContinuationLocalStorage();
 var storage = new exports.storage.InMemoryStorage({ max: 100, maxAge: 1000 * 60 * 60 });
 
 exports.configure = configure;
@@ -74,12 +76,12 @@ function handleRequest(enable, authorize, req, res) {
     }
 
     if (!requestPath.startsWith(resourcePath)) {
-      var id = startProfiling(req, enabled, authorized);
+      var extension = startProfiling(req, enabled, authorized);
       if (enabled) {
         res.on('finish', () => {
-          stopProfiling(req);
+          stopProfiling(extension, req);
         });
-        res.setHeader('X-MiniProfiler-Ids', `["${id}"]`);
+        res.setHeader('X-MiniProfiler-Ids', `["${extension.id}"]`);
       }
       return resolve(false);
     }
@@ -278,22 +280,21 @@ function include(id) {
     return enabled && authorized ? include(currentRequestExtension.id) : '';
   };
 
-  request.miniprofiler = currentRequestExtension;
-  return currentRequestExtension.id;
+  cls.setContext(currentRequestExtension);
+  Object.defineProperty(request, 'miniprofiler',  { get: () => cls.getContext() });
+
+  return currentRequestExtension;
 }
 
 /*
  * Stops profiling the given request.
  */
- function stopProfiling(request){
-  var extension = request.miniprofiler;
+ function stopProfiling(extension, request){
   var time = process.hrtime();
 
   extension.stopTime = time;
   extension.stepGraph.stopTime = time;
 
-  delete request.miniprofiler;
-
   var json = describePerformance(extension, request);
   storage.set(extension.id, JSON.stringify(json));
 }

package.json

@@ -26,6 +26,7 @@
   "license": "Apache-2.0",
   "readmeFilename": "README.md",
   "dependencies": {
+    "asyncctx": "^1.0.9",
     "lru-cache": "^4.0.1"
   },
   "tags": [

tests/concurrent-async-test.js

@@ -0,0 +1,37 @@
+'use strict';
+
+var expect = require('chai').expect;
+
+module.exports = function(server) {
+  describe('Concurrent Async Requests', function() {
+    before(server.setUp.bind(null, 'async'));
+    after(server.tearDown);
+
+    it('Each profile runs on its own context', function(done) {
+      let countDone = 0;
+      const partialDone = () => { if (++countDone === 2) done(); };
+
+      server.get('/', (err, response) => {
+        var ids = JSON.parse(response.headers['x-miniprofiler-ids']);
+        expect(ids).to.have.lengthOf(1);
+
+        server.post('/mini-profiler-resources/results/', { id: ids[0], popup: 1 }, (err, response, body) => {
+          var result = JSON.parse(body);
+          expect(result.Root.CustomTimings.async).to.have.lengthOf(2);
+          partialDone();
+        });
+      });
+
+      server.get('/?once=true', (err, response) => {
+        var ids = JSON.parse(response.headers['x-miniprofiler-ids']);
+        expect(ids).to.have.lengthOf(1);
+
+        server.post('/mini-profiler-resources/results/', { id: ids[0], popup: 1 }, (err, response, body) => {
+          var result = JSON.parse(body);
+          expect(result.Root.CustomTimings.async).to.have.lengthOf(1);
+          partialDone();
+        });
+      });
+    });
+  });
+};

tests/servers/async-provider.js

@@ -0,0 +1,21 @@
+'use strict';
+
+module.exports = function(obj) {
+  return {
+    name: 'dummy-async',
+    handler: function(req, res, next) {
+      obj.asyncFn = function() {
+        const timing = req.miniprofiler.startTimeQuery('async', 'dummy call');
+
+        return new Promise(resolve => {
+          setTimeout(() => {
+            req.miniprofiler.stopTimeQuery(timing);
+            resolve();
+          }, 25);
+        });
+      };
+
+      next();
+    }
+  };
+};

tests/servers/dummy-module.js

@@ -0,0 +1,5 @@
+'use strict';
+
+module.exports = {
+	asyncFn: () => Promise.resolve()
+};

tests/servers/express/async.js

@@ -0,0 +1,19 @@
+'use strict';
+
+var miniprofiler = require('../../../lib/miniprofiler.js');
+var dummyModule = require('../dummy-module');
+var express = require('express');
+
+var app = express();
+
+app.use(miniprofiler.express());
+app.use(miniprofiler.express.for(require('../async-provider.js')(dummyModule)));
+
+app.get('/', (req, res) => {
+	dummyModule.asyncFn().then(() => {
+		Promise.resolve(req.query.once ? undefined : dummyModule.asyncFn())
+      .then(() => res.send(res.locals.miniprofiler.include()));
+	});
+});
+
+module.exports = app;

tests/servers/hapi/async.js

@@ -0,0 +1,29 @@
+'use strict';
+
+var miniprofiler = require('../../../lib/miniprofiler.js');
+var dummyModule = require('../dummy-module');
+const Hapi = require('hapi');
+
+const server = new Hapi.Server();
+server.connection({ port: 8083 });
+
+server.register(miniprofiler.hapi(), (err) => {
+  if (err) throw err;
+});
+
+server.register(miniprofiler.hapi.for(require('../async-provider.js')(dummyModule)), (err) => {
+  if (err) throw err;
+});
+
+server.route({
+  method: 'GET',
+  path:'/',
+  handler: function(request, reply) {
+    dummyModule.asyncFn().then(() => {
+      Promise.resolve(request.query.once ? undefined : dummyModule.asyncFn())
+        .then(() => reply(request.app.miniprofiler.include()));
+    });
+  }
+});
+
+module.exports = server;

tests/servers/koa/async.js

@@ -0,0 +1,19 @@
+'use strict';
+
+var miniprofiler = require('../../../lib/miniprofiler.js');
+var dummyModule = require('../dummy-module');
+var koa = require('koa');
+var route = require('koa-route');
+var app = koa();
+
+app.use(miniprofiler.koa());
+app.use(miniprofiler.koa.for(require('../async-provider.js')(dummyModule)));
+
+app.use(route.get('/', function *(){
+  yield dummyModule.asyncFn().then(() => {
+    return Promise.resolve(this.query.once ? undefined : dummyModule.asyncFn())
+      .then(() => { this.body = this.state.miniprofiler.include(); });
+  });
+}));
+
+module.exports = app;