From 5ec35f3e1145f0231779e4d7047277840d827eab Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Fri, 24 Nov 2017 15:18:39 +0100 Subject: [PATCH 1/7] refactor(*): use async_hooks for Node.js 8.1.0 and above Fixes #75 --- .travis.yml | 8 ++ docs/compatibility.asciidoc | 3 +- lib/config.js | 3 + lib/instrumentation/async-hooks.js | 37 ++++++++ lib/instrumentation/index.js | 7 +- package.json | 3 +- test/agent.js | 1 + test/instrumentation/async-hooks.js | 120 ++++++++++++++++++++++++ test/instrumentation/github-issue-75.js | 71 ++++++++++++++ 9 files changed, 250 insertions(+), 3 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/.travis.yml b/.travis.yml index 0c81bcdc07..e733af1f29 100644 --- a/.travis.yml +++ b/.travis.yml @@ -35,6 +35,14 @@ jobs: # TEST STAGE # ########################################### + # Async Hooks + - + node_js: '9' + env: ELASTIC_APM_FF_ASYNC_HOOKS=1 + - + node_js: '8' + env: ELASTIC_APM_FF_ASYNC_HOOKS=1 + # Docs - script: npm run docs diff --git a/docs/compatibility.asciidoc b/docs/compatibility.asciidoc index 5d591d3ecd..233576cd84 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/config.js b/lib/config.js index 451ee84a79..40e0d24678 100644 --- a/lib/config.js +++ b/lib/config.js @@ -34,6 +34,7 @@ var DEFAULTS = { errorOnAbortedRequests: false, abortedErrorThreshold: 25000, instrument: true, + ff_asyncHooks: false, ff_captureFrame: false, sourceContext: true } @@ -57,6 +58,7 @@ var ENV_TABLE = { instrument: 'ELASTIC_APM_INSTRUMENT', flushInterval: 'ELASTIC_APM_FLUSH_INTERVAL', maxQueueSize: 'ELASTIC_APM_MAX_QUEUE_SIZE', + ff_asyncHooks: 'ELASTIC_APM_FF_ASYNC_HOOKS', ff_captureFrame: 'ELASTIC_APM_FF_CAPTURE_FRAME', sourceContext: 'ELASTIC_APM_SOURCE_CONTEXT' } @@ -70,6 +72,7 @@ var BOOL_OPTS = [ 'logBody', 'errorOnAbortedRequests', 'instrument', + 'ff_asyncHooks', 'ff_captureFrame', 'sourceContext' ] diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js new file mode 100644 index 0000000000..6aad5c65d1 --- /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 139df8ec75..471b3abb0b 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 (this._agent._conf.ff_asyncHooks && 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 2b79193c59..0dd808f6f9 100644 --- a/package.json +++ b/package.json @@ -17,7 +17,7 @@ "test": "npm run check && node test/test.js", "posttest": "test/posttest.sh", "test-cli": "node test/script/cli.js", - "test-deps": "dependency-check . && dependency-check . --unused --no-dev --entry lib/instrumentation/modules/*" + "test-deps": "dependency-check . -i async_hooks && dependency-check . --unused --no-dev --entry lib/instrumentation/modules/*" }, "directories": { "test": "test" @@ -112,6 +112,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/agent.js b/test/agent.js index f0844ad776..a40cf51f03 100644 --- a/test/agent.js +++ b/test/agent.js @@ -26,6 +26,7 @@ var optionFixtures = [ ['stackTraceLimit', 'STACK_TRACE_LIMIT', Infinity], ['captureExceptions', 'CAPTURE_EXCEPTIONS', true], ['instrument', 'INSTRUMENT', true], + ['ff_asyncHooks', 'FF_ASYNC_HOOKS', false], ['ff_captureFrame', 'FF_CAPTURE_FRAME', false] ] diff --git a/test/instrumentation/async-hooks.js b/test/instrumentation/async-hooks.js new file mode 100644 index 0000000000..dd4d03dc5a --- /dev/null +++ b/test/instrumentation/async-hooks.js @@ -0,0 +1,120 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false, + ff_asyncHooks: true +}) +var ins = agent._instrumentation + +var test = require('tape') +var semver = require('semver') + +test('setTimeout', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + setTimeout(function () { + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }, 50) + }) +}) + +test('setInterval', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + var timer = setInterval(function () { + clearInterval(timer) + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }, 50) + }) +}) + +test('setImmediate', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + setImmediate(function () { + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) +}) + +test('process.nextTick', function (t) { + t.plan(2) + twice(function () { + var trans = agent.startTransaction() + process.nextTick(function () { + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) +}) + +// We can't instrument ore-defined promises properly without async-hooks, so +// lets not run these tests on versions of Node.js without async-hooks +if (semver.gte(process.version, '8.1.0')) { + test('pre-defined, pre-resolved shared promise', function (t) { + t.plan(4) + + var p = Promise.resolve('success') + + twice(function () { + var trans = agent.startTransaction() + p.then(function (result) { + t.equal(result, 'success') + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) + }) + + test('pre-defined, pre-resolved non-shared promise', function (t) { + t.plan(4) + + twice(function () { + var p = Promise.resolve('success') + var trans = agent.startTransaction() + p.then(function (result) { + t.equal(result, 'success') + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) + }) + + test('pre-defined, post-resolved promise', function (t) { + t.plan(4) + twice(function () { + var p = new Promise(function (resolve) { + setTimeout(function () { + resolve('success') + }, 20) + }) + var trans = agent.startTransaction() + p.then(function (result) { + t.equal(result, 'success') + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) + }) +} + +test('post-defined, post-resolved promise', function (t) { + t.plan(4) + twice(function () { + var trans = agent.startTransaction() + var p = new Promise(function (resolve) { + setTimeout(function () { + resolve('success') + }, 20) + }) + p.then(function (result) { + t.equal(result, 'success') + t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id) + }) + }) +}) + +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 0000000000..692e5b1b21 --- /dev/null +++ b/test/instrumentation/github-issue-75.js @@ -0,0 +1,71 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false, + ff_asyncHooks: true +}) + +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 } +} From 60e2bf7a557b5c3ce94b57a1618468c04e4d67d9 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Tue, 19 Dec 2017 12:02:00 +0100 Subject: [PATCH 2/7] Simplify async_hooks logic --- lib/instrumentation/async-hooks.js | 34 ++++++++++++++---------------- 1 file changed, 16 insertions(+), 18 deletions(-) diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js index 6aad5c65d1..86ee7e8dc8 100644 --- a/lib/instrumentation/async-hooks.js +++ b/lib/instrumentation/async-hooks.js @@ -3,9 +3,19 @@ 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() + const asyncHook = asyncHooks.createHook({init, destroy}) + const transactions = new Map() + + Object.defineProperty(ins, 'currentTransaction', { + get: function () { + const asyncId = asyncHooks.executionAsyncId() + return transactions.get(asyncId) + }, + set: function (trans) { + const asyncId = asyncHooks.executionAsyncId() + transactions.set(asyncId, trans) + } + }) asyncHook.enable() @@ -15,23 +25,11 @@ module.exports = function (ins) { // 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) + transactions.set(asyncId, ins.currentTransaction) } function destroy (asyncId) { - if (!initState.has(asyncId)) return // in case type === TIMERWRAP - initState.delete(asyncId) - beforeState.delete(asyncId) + if (!transactions.has(asyncId)) return // in case type === TIMERWRAP + transactions.delete(asyncId) } } From 63b4be04e927676fc30b2975288de28df8484ced Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Sat, 23 Dec 2017 10:38:09 +0100 Subject: [PATCH 3/7] default to async hooks on --- lib/config.js | 6 +++--- lib/instrumentation/index.js | 2 +- test/agent.js | 2 +- test/instrumentation/async-hooks.js | 3 +-- test/instrumentation/github-issue-75.js | 3 +-- 5 files changed, 7 insertions(+), 9 deletions(-) diff --git a/lib/config.js b/lib/config.js index 40e0d24678..14d5815339 100644 --- a/lib/config.js +++ b/lib/config.js @@ -34,7 +34,7 @@ var DEFAULTS = { errorOnAbortedRequests: false, abortedErrorThreshold: 25000, instrument: true, - ff_asyncHooks: false, + asyncHooks: true, ff_captureFrame: false, sourceContext: true } @@ -58,7 +58,7 @@ var ENV_TABLE = { instrument: 'ELASTIC_APM_INSTRUMENT', flushInterval: 'ELASTIC_APM_FLUSH_INTERVAL', maxQueueSize: 'ELASTIC_APM_MAX_QUEUE_SIZE', - ff_asyncHooks: 'ELASTIC_APM_FF_ASYNC_HOOKS', + asyncHooks: 'ELASTIC_APM_ASYNC_HOOKS', ff_captureFrame: 'ELASTIC_APM_FF_CAPTURE_FRAME', sourceContext: 'ELASTIC_APM_SOURCE_CONTEXT' } @@ -72,7 +72,7 @@ var BOOL_OPTS = [ 'logBody', 'errorOnAbortedRequests', 'instrument', - 'ff_asyncHooks', + 'asyncHooks', 'ff_captureFrame', 'sourceContext' ] diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index 471b3abb0b..029a694036 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -41,7 +41,7 @@ Instrumentation.prototype.start = function () { }) }) - if (this._agent._conf.ff_asyncHooks && semver.gte(process.version, '8.1.0')) { + if (this._agent._conf.asyncHooks && semver.gte(process.version, '8.1.0')) { require('./async-hooks')(this) } else { require('./patch-async')(this) diff --git a/test/agent.js b/test/agent.js index a40cf51f03..82be380b4b 100644 --- a/test/agent.js +++ b/test/agent.js @@ -26,7 +26,7 @@ var optionFixtures = [ ['stackTraceLimit', 'STACK_TRACE_LIMIT', Infinity], ['captureExceptions', 'CAPTURE_EXCEPTIONS', true], ['instrument', 'INSTRUMENT', true], - ['ff_asyncHooks', 'FF_ASYNC_HOOKS', false], + ['asyncHooks', 'ASYNC_HOOKS', true], ['ff_captureFrame', 'FF_CAPTURE_FRAME', false] ] diff --git a/test/instrumentation/async-hooks.js b/test/instrumentation/async-hooks.js index dd4d03dc5a..f9b4cc7e7a 100644 --- a/test/instrumentation/async-hooks.js +++ b/test/instrumentation/async-hooks.js @@ -2,8 +2,7 @@ var agent = require('../..').start({ appName: 'test', - captureExceptions: false, - ff_asyncHooks: true + captureExceptions: false }) var ins = agent._instrumentation diff --git a/test/instrumentation/github-issue-75.js b/test/instrumentation/github-issue-75.js index 692e5b1b21..f94d4db54e 100644 --- a/test/instrumentation/github-issue-75.js +++ b/test/instrumentation/github-issue-75.js @@ -2,8 +2,7 @@ var agent = require('../..').start({ appName: 'test', - captureExceptions: false, - ff_asyncHooks: true + captureExceptions: false }) var http = require('http') From 74552f129093a46cab6944d2bd62b109f5125bac Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Sat, 23 Dec 2017 10:38:23 +0100 Subject: [PATCH 4/7] Address PR comments --- lib/instrumentation/async-hooks.js | 2 +- lib/instrumentation/index.js | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js index 86ee7e8dc8..0429414665 100644 --- a/lib/instrumentation/async-hooks.js +++ b/lib/instrumentation/async-hooks.js @@ -9,7 +9,7 @@ module.exports = function (ins) { Object.defineProperty(ins, 'currentTransaction', { get: function () { const asyncId = asyncHooks.executionAsyncId() - return transactions.get(asyncId) + return transactions.has(asyncId) ? transactions.get(asyncId) : null }, set: function (trans) { const asyncId = asyncHooks.executionAsyncId() diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index 029a694036..4e8a8b66e4 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -41,7 +41,7 @@ Instrumentation.prototype.start = function () { }) }) - if (this._agent._conf.asyncHooks && semver.gte(process.version, '8.1.0')) { + if (this._agent._conf.asyncHooks && semver.gte(process.version, '8.2.0')) { require('./async-hooks')(this) } else { require('./patch-async')(this) From baff5e0b5b6c399e6e9eac2c99f00fb7d0f96c74 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Sat, 23 Dec 2017 10:38:46 +0100 Subject: [PATCH 5/7] update docs --- docs/agent-api.asciidoc | 15 +++++++++++++++ docs/compatibility.asciidoc | 11 +++++++++-- 2 files changed, 24 insertions(+), 2 deletions(-) diff --git a/docs/agent-api.asciidoc b/docs/agent-api.asciidoc index d6abd91288..6772e78384 100644 --- a/docs/agent-api.asciidoc +++ b/docs/agent-api.asciidoc @@ -150,6 +150,21 @@ A boolean specifying if the agent should collect performance metrics for the app Note that both `active` and `instrument` needs to be `true` for instrumentation to be running. +[[async-hooks]] +===== `asyncHooks` + +* *Type:* Boolean +* *Default:* `true` +* *Env:* `ELASTIC_APM_ASYNC_HOOKS` + +A boolean specifying if the agent should use the experimental https://nodejs.org/api/async_hooks.html[Async Hooks] API found in Node.js version 8.2.0 and above. +This setting have no effect when running a Node.js version older than 8.2.0. + +If you experience any issues related to using Async Hooks, +please https://github.com/elastic/apm-agent-nodejs/issues[open an issue]. + +Note that not all core Node.js API's can be instrumented without the use of Async Hooks if running Node.js 8 or above. + [[ignore-urls]] ===== `ignoreUrls` diff --git a/docs/compatibility.asciidoc b/docs/compatibility.asciidoc index 233576cd84..78aba33fba 100644 --- a/docs/compatibility.asciidoc +++ b/docs/compatibility.asciidoc @@ -7,8 +7,15 @@ 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.1.0 or higher to get full support -- v8.0.0 - Recommended solution: Upgrade to v8.1.0 or higher to get full support +- v7.10.x - Recommended solution: Upgrade to v8.2.0 or higher to get full support +- v8.0.x - Recommended solution: Upgrade to v8.2.0 or higher to get full support +- v8.1.x - Recommended solution: Upgrade to v8.2.0 or higher to get full support + +NOTE: Support for Node.js 8.2.0 and above is experimental as it makes use the experimental core API https://nodejs.org/api/async_hooks.html[Async Hooks]. +If you experience any issues related to using Async Hooks, +you can always disable the use of this API by setting the <> config option to `false`. +Note however, +that not all core Node.js API's can be instrumented without the use of Async Hooks if running Node.js 8 or above. [float] [[compatibility-frameworks]] From db9b1209afc04e2c51c8e3d150574755dde48375 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Sat, 23 Dec 2017 10:41:19 +0100 Subject: [PATCH 6/7] fix travis --- .travis.yml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/.travis.yml b/.travis.yml index e733af1f29..9c4b3573e3 100644 --- a/.travis.yml +++ b/.travis.yml @@ -35,13 +35,13 @@ jobs: # TEST STAGE # ########################################### - # Async Hooks + # Disable Async Hooks - node_js: '9' - env: ELASTIC_APM_FF_ASYNC_HOOKS=1 + env: ELASTIC_APM_ASYNC_HOOKS=0 - node_js: '8' - env: ELASTIC_APM_FF_ASYNC_HOOKS=1 + env: ELASTIC_APM_ASYNC_HOOKS=0 # Docs - From 6a384ffa48d0d178157a27fe6f08cec44e443d76 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Sat, 23 Dec 2017 10:46:12 +0100 Subject: [PATCH 7/7] fix tests --- test/instrumentation/async-hooks.js | 5 +++-- test/instrumentation/github-issue-75.js | 3 ++- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/test/instrumentation/async-hooks.js b/test/instrumentation/async-hooks.js index f9b4cc7e7a..ad8cfacb60 100644 --- a/test/instrumentation/async-hooks.js +++ b/test/instrumentation/async-hooks.js @@ -2,7 +2,8 @@ var agent = require('../..').start({ appName: 'test', - captureExceptions: false + captureExceptions: false, + asyncHooks: true }) var ins = agent._instrumentation @@ -52,7 +53,7 @@ test('process.nextTick', function (t) { // We can't instrument ore-defined promises properly without async-hooks, so // lets not run these tests on versions of Node.js without async-hooks -if (semver.gte(process.version, '8.1.0')) { +if (semver.gte(process.version, '8.2.0')) { test('pre-defined, pre-resolved shared promise', function (t) { t.plan(4) diff --git a/test/instrumentation/github-issue-75.js b/test/instrumentation/github-issue-75.js index f94d4db54e..ea0e7cefeb 100644 --- a/test/instrumentation/github-issue-75.js +++ b/test/instrumentation/github-issue-75.js @@ -2,7 +2,8 @@ var agent = require('../..').start({ appName: 'test', - captureExceptions: false + captureExceptions: false, + asyncHooks: true }) var http = require('http')