Handle context between two async requests

This commit fixes a bug where a request can end without finishing its
timings. See: MiniProfiler#4

Bug cause: The structure that is used to register Miniprofiler timing
providers, like (Postgres, HTTP, Redis), because it overrides the
original method (globally) and uses the `request` object to access the
Miniprofiler extensions to build the timings, and this doesn't work in a
scenario with simultaneous requests using an async provider.

Here is an example using
[`pg`](https://github.com/goenning/miniprofiler-pg/blob/master/index.js)
to try illustrating the failing scenario (check out the
`tests/concurrent-async-test.js` test to see it running).

request A start:
* `pg.Client.prototype.query` holds a `req` object of requestA.
* It calls `.query` in a pg instance
  * A miniprofiler timing starts with the call to
    `req.miniprofiler.timeQuery(...)`
  * The original method is called (async).

request B start:
* `pg.Client.prototype.query` holds a `req` object of request B.
* It calls `.query` in a pg instance
  * Start timing with `req.miniprofiler.timeQuery(...)`
  * The original method is called (async).

request A resume:
* The result of `.query` is returned
* A new call to  `.query` is made
  * This time the `req` points to request B, this means that
    `req.miniprofiler.timeQuery(...)` will start a timing on request B.
  * The original method is called (async)

request B resume:
* The result of `.query` is returned.
* All data was fetched, the request is ready to finish, so internally
  Miniprofile calls
  [`stopProfilling`](https://github.com/MiniProfiler/node/blob/1a98e40698b1126ac8de728a33406656361f8870/lib/miniprofiler.js#L80).
  * This fails because there is a timing started (by request A) but not
    finished, so calculating the
    [diffs](https://github.com/MiniProfiler/node/blob/1a98e40698b1126ac8de728a33406656361f8870/lib/miniprofiler.js#L409)
    will fails because `stop` is undefined.

Solution
--------

Using NodeJS "async_hooks" we can track the reference to the correct
extension for each request, so calls to `req.miniprofiler.timeQuery()`
will point to the correct miniprofiler extension.

To check some performance analisys see:
nodejs/node#14794 (comment)

The goal of the current commit isn't introduce breaking changes, so the
miniprofiler reference is injected into the request using JS getters.

Another solution is changing the API for providers, where instead of
receiving a `req` reference, they can receive a function that gets the
reference to the correct miniprofiler instance. But this will break API
with all existing providers.

References
----------

- https://medium.com/the-node-js-collection/async-hooks-in-node-js-illustrated-b7ce1344111f
- https://medium.com/@guysegev/async-hooks-a-whole-new-world-of-opportunities-a1a6daf1990a
- nodejs/node#14794 (comment)

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;