From bfc5f928409c3e7f51da20eaba176fa4c3765226 Mon Sep 17 00:00:00 2001 From: Danilo Resende Date: Fri, 19 Oct 2018 18:23:49 -0300 Subject: [PATCH] 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..74ac636 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;