From f2d02e49b11f42655a9fe3a50b8333b0ac1fb5d9 Mon Sep 17 00:00:00 2001
From: Danilo Resende <danilo.resende@toptal.com>
Date: Fri, 19 Oct 2018 18:23:49 -0300
Subject: [PATCH 1/4] Handle context between two async requests

This commit fixes a bug where a request can end without finishing its
timings. See: https://github.com/MiniProfiler/node/pull/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:
https://github.com/nodejs/node/issues/14794#issuecomment-335645401

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
- https://github.com/nodejs/node/issues/14794#issuecomment-335645401
---
 lib/miniprofiler.js             | 19 +++++++++--------
 package.json                    |  1 +
 tests/concurrent-async-test.js  | 37 +++++++++++++++++++++++++++++++++
 tests/servers/async-provider.js | 21 +++++++++++++++++++
 tests/servers/dummy-module.js   |  5 +++++
 tests/servers/express/async.js  | 19 +++++++++++++++++
 tests/servers/hapi/async.js     | 29 ++++++++++++++++++++++++++
 tests/servers/koa/async.js      | 19 +++++++++++++++++
 8 files changed, 141 insertions(+), 9 deletions(-)
 create mode 100644 tests/concurrent-async-test.js
 create mode 100644 tests/servers/async-provider.js
 create mode 100644 tests/servers/dummy-module.js
 create mode 100644 tests/servers/express/async.js
 create mode 100644 tests/servers/hapi/async.js
 create mode 100644 tests/servers/koa/async.js

diff --git a/lib/miniprofiler.js b/lib/miniprofiler.js
index 086be80..6075560 100755
--- a/lib/miniprofiler.js
+++ b/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));
 }
diff --git a/package.json b/package.json
index 2b7a70d..af3e9dc 100644
--- a/package.json
+++ b/package.json
@@ -26,6 +26,7 @@
   "license": "Apache-2.0",
   "readmeFilename": "README.md",
   "dependencies": {
+    "asyncctx": "^1.0.9",
     "lru-cache": "^4.0.1"
   },
   "tags": [
diff --git a/tests/concurrent-async-test.js b/tests/concurrent-async-test.js
new file mode 100644
index 0000000..4ecaa52
--- /dev/null
+++ b/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();
+        });
+      });
+    });
+  });
+};
diff --git a/tests/servers/async-provider.js b/tests/servers/async-provider.js
new file mode 100644
index 0000000..1d6138f
--- /dev/null
+++ b/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();
+    }
+  };
+};
diff --git a/tests/servers/dummy-module.js b/tests/servers/dummy-module.js
new file mode 100644
index 0000000..df48e6c
--- /dev/null
+++ b/tests/servers/dummy-module.js
@@ -0,0 +1,5 @@
+'use strict';
+
+module.exports = {
+	asyncFn: () => Promise.resolve()
+};
diff --git a/tests/servers/express/async.js b/tests/servers/express/async.js
new file mode 100644
index 0000000..39fd990
--- /dev/null
+++ b/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;
diff --git a/tests/servers/hapi/async.js b/tests/servers/hapi/async.js
new file mode 100644
index 0000000..287df6a
--- /dev/null
+++ b/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;
diff --git a/tests/servers/koa/async.js b/tests/servers/koa/async.js
new file mode 100644
index 0000000..9ee045c
--- /dev/null
+++ b/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;

From c39c8a37fc4da155fa150928a6d3aa363e5f68c6 Mon Sep 17 00:00:00 2001
From: Danilo Resende <danilo.resende@toptal.com>
Date: Tue, 6 Nov 2018 09:58:58 -0200
Subject: [PATCH 2/4] Update asyncctx

---
 package.json | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/package.json b/package.json
index af3e9dc..5bd36c9 100644
--- a/package.json
+++ b/package.json
@@ -26,7 +26,7 @@
   "license": "Apache-2.0",
   "readmeFilename": "README.md",
   "dependencies": {
-    "asyncctx": "^1.0.9",
+    "asyncctx": "^1.1.0",
     "lru-cache": "^4.0.1"
   },
   "tags": [

From 44e8197496c437adaa0fcf5576b1ad2f82076c3a Mon Sep 17 00:00:00 2001
From: Danilo Resende <danilo.resende@toptal.com>
Date: Tue, 20 Nov 2018 14:52:17 -0200
Subject: [PATCH 3/4] Lock "debug" dependency to work on Node v4

Koa adds dependency to `"debug": "*"` which fetch a version non
compatible with Node v4. Locking it on our package.json fix this issue.
---
 package.json | 1 +
 1 file changed, 1 insertion(+)

diff --git a/package.json b/package.json
index 5bd36c9..cb34b6c 100644
--- a/package.json
+++ b/package.json
@@ -47,6 +47,7 @@
     "koa": "^1.2.1",
     "koa-route": "^2.4.2",
     "koa-views": "^4.1.0",
+    "debug": "^2.6.1",
     "mocha": "^2.5.3",
     "pug": "^2.0.0-beta2",
     "redis": "^2.6.1",

From 7f9fa5efe5688e3c546f847740cf8665ca173a05 Mon Sep 17 00:00:00 2001
From: Danilo Resende <danilo.resende@toptal.com>
Date: Mon, 26 Nov 2018 00:04:46 -0200
Subject: [PATCH 4/4] Drop Node version < 8

After more testing the 'async-hooks' polyfill shown to not work properly
for Node version prior to 8.
---
 .travis.yml                |  3 +--
 lib/async-context.js       | 28 ++++++++++++++++++++++++++++
 lib/middlewares/express.js |  9 +++++++--
 lib/middlewares/hapi.js    |  6 +++++-
 lib/middlewares/koa.js     |  7 ++++++-
 lib/miniprofiler.js        |  5 +----
 package.json               |  3 +--
 7 files changed, 49 insertions(+), 12 deletions(-)
 create mode 100644 lib/async-context.js

diff --git a/.travis.yml b/.travis.yml
index 1f3333f..9d9ea1c 100755
--- a/.travis.yml
+++ b/.travis.yml
@@ -1,7 +1,6 @@
 language: node_js
 node_js:
-  - "4"
-  - "5"
+  - "8"
   - "stable"
 
 sudo: required
diff --git a/lib/async-context.js b/lib/async-context.js
new file mode 100644
index 0000000..60d0ef2
--- /dev/null
+++ b/lib/async-context.js
@@ -0,0 +1,28 @@
+'use strict';
+
+const asyncHooks = require('async_hooks');
+
+class AsyncContext {
+  constructor() {
+    this.map = new Map();
+    asyncHooks.createHook({
+      init: (id, _type, triggerId) => {
+        if (this.map.has(triggerId))
+          this.map.set(id, this.map.get(triggerId));
+      },
+      destroy: (id) => this.map.delete(id)
+    }).enable();
+  }
+
+  get() {
+    const id = asyncHooks.executionAsyncId();
+    if (this.map.has(id))
+      return this.map.get(id);
+  }
+
+  set(val) {
+    this.map.set(asyncHooks.executionAsyncId(), val);
+  }
+}
+
+module.exports = new AsyncContext();
diff --git a/lib/middlewares/express.js b/lib/middlewares/express.js
index a99046d..878174d 100755
--- a/lib/middlewares/express.js
+++ b/lib/middlewares/express.js
@@ -1,16 +1,21 @@
 'use strict';
 
+const asyncContext = require('../async-context');
+
 module.exports = {
   buildMiddleware: function(provider) {
     return function(req, res, next) {
       provider.handler(req, res, next);
     };
   },
-  mainMiddleware: function(enable, authorize, handleRequest) {
+  mainMiddleware: function(enable, authorize, handleRequest, cls) {
     return function(req, res, next) {
       handleRequest(enable, authorize, req, res).then((handled) => {
         res.locals.miniprofiler = req.miniprofiler;
 
+        asyncContext.set(req.miniprofiler);
+        Object.defineProperty(req, 'miniprofiler', { get: () => asyncContext.get() });
+
         var render = res.render;
         res.render = function() {
           var renderArguments = arguments;
@@ -24,4 +29,4 @@ module.exports = {
       }).catch(next);
     };
   }
-};
\ No newline at end of file
+};
diff --git a/lib/middlewares/hapi.js b/lib/middlewares/hapi.js
index 4090808..79797e5 100755
--- a/lib/middlewares/hapi.js
+++ b/lib/middlewares/hapi.js
@@ -1,5 +1,7 @@
 'use strict';
 
+const asyncContext = require('../async-context');
+
 module.exports = {
   buildMiddleware: function(provider) {
     var plugin = {
@@ -25,7 +27,9 @@ module.exports = {
       register: (server, options, next) => {
         server.ext('onRequest', function(request, reply) {
           handleRequest(enable, authorize, request.raw.req, request.raw.res).then((handled) => {
-            request.app.miniprofiler = request.raw.req.miniprofiler;
+            asyncContext.set(request.raw.req.miniprofiler);
+            Object.defineProperty(request.app, 'miniprofiler', { get: () => asyncContext.get() });
+            Object.defineProperty(request.raw.req, 'miniprofiler', { get: () => asyncContext.get() });
 
             if (!handled)
               reply.continue();
diff --git a/lib/middlewares/koa.js b/lib/middlewares/koa.js
index 74c0ad4..44269bd 100755
--- a/lib/middlewares/koa.js
+++ b/lib/middlewares/koa.js
@@ -1,5 +1,7 @@
 'use strict';
 
+const asyncContext = require('../async-context');
+
 module.exports = {
   buildMiddleware: function(provider) {
     return function *(next) {
@@ -12,7 +14,10 @@ module.exports = {
   mainMiddleware: function(enable, authorize, handleRequest) {
     return function *(next) {
       var handled = yield handleRequest(enable, authorize, this.req, this.res);
-      this.state.miniprofiler = this.req.miniprofiler;
+
+      asyncContext.set(this.req.miniprofiler);
+      Object.defineProperty(this.state, 'miniprofiler', { get: () => asyncContext.get() });
+      Object.defineProperty(this.req, 'miniprofiler', { get: () => asyncContext.get() });
 
       if (this.render) {
         var render = this.render;
diff --git a/lib/miniprofiler.js b/lib/miniprofiler.js
index 6075560..3f2a2f4 100755
--- a/lib/miniprofiler.js
+++ b/lib/miniprofiler.js
@@ -15,7 +15,6 @@
  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 = [];
@@ -28,7 +27,6 @@ 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;
@@ -280,8 +278,7 @@ function include(id) {
     return enabled && authorized ? include(currentRequestExtension.id) : '';
   };
 
-  cls.setContext(currentRequestExtension);
-  Object.defineProperty(request, 'miniprofiler', { get: () => cls.getContext() });
+  request.miniprofiler = currentRequestExtension;
 
   return currentRequestExtension;
 }
diff --git a/package.json b/package.json
index cb34b6c..a443956 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "miniprofiler",
-  "version": "1.2.3",
+  "version": "2.0.0",
   "description": "A simple but effective mini-profiler.",
   "main": "lib/miniprofiler.js",
   "scripts": {
@@ -26,7 +26,6 @@
   "license": "Apache-2.0",
   "readmeFilename": "README.md",
   "dependencies": {
-    "asyncctx": "^1.1.0",
     "lru-cache": "^4.0.1"
   },
   "tags": [