From 6ee9f1c113f3b4e568aa41e5d17d788bb7ae5646 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Fri, 24 Nov 2017 15:18:39 +0100 Subject: [PATCH] refactor(*): use async_hooks for Node.js 8.1.0 and above Fixes #75 --- docs/compatibility.asciidoc | 3 +- lib/instrumentation/async-hooks.js | 37 +++++++++++++ lib/instrumentation/index.js | 7 ++- package.json | 1 + test/instrumentation/async-hooks.js | 55 +++++++++++++++++++ test/instrumentation/github-issue-75.js | 70 +++++++++++++++++++++++++ 6 files changed, 171 insertions(+), 2 deletions(-) create mode 100644 lib/instrumentation/async-hooks.js create mode 100644 test/instrumentation/async-hooks.js create mode 100644 test/instrumentation/github-issue-75.js diff --git a/docs/compatibility.asciidoc b/docs/compatibility.asciidoc index c29f9e7076f..88dbea5aa55 100644 --- a/docs/compatibility.asciidoc +++ b/docs/compatibility.asciidoc @@ -7,7 +7,8 @@ Previous versions of Node.js are not supported. Some versions of Node.js contain bugs or issues that limit our ability to instrument them correctly. The following versions of Node.js are known to not be fully instrumented: -- v7.10.x - Recommended solution: Upgrade to v8.0.0 or higher to get full support +- v7.10.x - Recommended solution: Upgrade to v8.1.0 or higher to get full support +- v8.0.0 - Recommended solution: Upgrade to v8.1.0 or higher to get full support [float] [[compatibility-frameworks]] diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js new file mode 100644 index 00000000000..6aad5c65d10 --- /dev/null +++ b/lib/instrumentation/async-hooks.js @@ -0,0 +1,37 @@ +'use strict' + +const asyncHooks = require('async_hooks') + +module.exports = function (ins) { + const asyncHook = asyncHooks.createHook({init, before, after, destroy}) + const initState = new Map() + const beforeState = new Map() + + asyncHook.enable() + + function init (asyncId, type, triggerAsyncId, resource) { + // We don't care about the TIMERWRAP, as it will only init once for each + // timer that shares the timeout value. Instead we rely on the Timeout + // type, which will init for each scheduled timer. + if (type === 'TIMERWRAP') return + + initState.set(asyncId, ins.currentTransaction) + } + + function before (asyncId) { + if (!initState.has(asyncId)) return // in case type === TIMERWRAP + beforeState.set(asyncId, ins.currentTransaction) + ins.currentTransaction = initState.get(asyncId) + } + + function after (asyncId) { + if (!initState.has(asyncId)) return // in case type === TIMERWRAP + ins.currentTransaction = beforeState.get(asyncId) + } + + function destroy (asyncId) { + if (!initState.has(asyncId)) return // in case type === TIMERWRAP + initState.delete(asyncId) + beforeState.delete(asyncId) + } +} diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index f3204df0efa..08eb60269b5 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -2,6 +2,7 @@ var fs = require('fs') var path = require('path') +var semver = require('semver') var hook = require('require-in-the-middle') var Transaction = require('./transaction') var Queue = require('./queue') @@ -40,7 +41,11 @@ Instrumentation.prototype.start = function () { }) }) - require('./patch-async')(this) + if (semver.gte(process.version, '8.1.0')) { + require('./async-hooks')(this) + } else { + require('./patch-async')(this) + } debug('shimming Module._load function') hook(MODULES, function (exports, name, basedir) { diff --git a/package.json b/package.json index 3dc76d8fbdb..2d77b6ebefb 100644 --- a/package.json +++ b/package.json @@ -102,6 +102,7 @@ "pg": "^7.1.0", "redis": "^2.6.3", "restify": "^4.3.0", + "send": "^0.16.1", "standard": "^10.0.2", "tape": "^4.8.0", "test-all-versions": "^3.1.1", diff --git a/test/instrumentation/async-hooks.js b/test/instrumentation/async-hooks.js new file mode 100644 index 00000000000..8311da9d8ef --- /dev/null +++ b/test/instrumentation/async-hooks.js @@ -0,0 +1,55 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false +}) +var ins = agent._instrumentation + +var test = require('tape') + +test('setTimeout', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + setTimeout(function () { + t.equal(ins.currentTransaction, trans) + }, 50) + }) +}) + +test('setInterval', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + var timer = setInterval(function () { + clearInterval(timer) + t.equal(ins.currentTransaction, trans) + }, 50) + }) +}) + +test('setImmediate', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + setImmediate(function () { + t.equal(ins.currentTransaction, trans) + }) + }) +}) + +test('process.nextTick', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + process.nextTick(function () { + t.equal(ins.currentTransaction, trans) + }) + }) +}) + +function twice (fn) { + setImmediate(fn) + setImmediate(fn) +} diff --git a/test/instrumentation/github-issue-75.js b/test/instrumentation/github-issue-75.js new file mode 100644 index 00000000000..f94d4db54e4 --- /dev/null +++ b/test/instrumentation/github-issue-75.js @@ -0,0 +1,70 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false +}) + +var http = require('http') +var send = require('send') +var test = require('tape') + +// run it 5 times in case of false positives due to race conditions +times(5, function (n, done) { + test('https://github.com/elastic/apm-agent-nodejs/issues/75 ' + n, function (t) { + resetAgent(function (endpoint, headers, data, cb) { + t.equal(data.transactions.length, 2, 'should create transactions') + data.transactions.forEach(function (trans) { + t.equal(trans.traces.length, 1, 'transaction should have one trace') + t.equal(trans.traces[0].name, trans.id, 'trace should belong to transaction') + }) + server.close() + t.end() + done() + }) + + var server = http.createServer(function (req, res) { + var trace = agent.buildTrace() + trace.start(agent._instrumentation.currentTransaction.id) + setTimeout(function () { + trace.end() + send(req, __filename).pipe(res) + }, 50) + }) + + var requestNo = 0 + + server.listen(function () { + request() + request() + }) + + function request () { + var port = server.address().port + http.get('http://localhost:' + port, function (res) { + res.on('end', function () { + if (++requestNo === 2) { + agent._instrumentation._queue._flush() + } + }) + res.resume() + }) + } + }) +}) + +function times (max, fn) { + var n = 0 + run() + function run () { + if (++n > max) return + fn(n, run) + } +} + +function resetAgent (cb) { + agent._instrumentation.currentTransaction = null + agent._instrumentation._queue._clear() + agent._httpClient = { request: cb || function () {} } + agent.captureError = function (err) { throw err } +}