diff --git a/.travis.yml b/.travis.yml index 0c81bcdc075..9c4b3573e33 100644 --- a/.travis.yml +++ b/.travis.yml @@ -35,6 +35,14 @@ jobs: # TEST STAGE # ########################################### + # Disable Async Hooks + - + node_js: '9' + env: ELASTIC_APM_ASYNC_HOOKS=0 + - + node_js: '8' + env: ELASTIC_APM_ASYNC_HOOKS=0 + # Docs - script: npm run docs diff --git a/docs/agent-api.asciidoc b/docs/agent-api.asciidoc index d6abd912888..6772e78384f 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 5d591d3ecd9..78aba33fba4 100644 --- a/docs/compatibility.asciidoc +++ b/docs/compatibility.asciidoc @@ -7,7 +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.0.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]] diff --git a/lib/config.js b/lib/config.js index 451ee84a798..14d5815339a 100644 --- a/lib/config.js +++ b/lib/config.js @@ -34,6 +34,7 @@ var DEFAULTS = { errorOnAbortedRequests: false, abortedErrorThreshold: 25000, instrument: true, + asyncHooks: true, 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', + asyncHooks: 'ELASTIC_APM_ASYNC_HOOKS', ff_captureFrame: 'ELASTIC_APM_FF_CAPTURE_FRAME', sourceContext: 'ELASTIC_APM_SOURCE_CONTEXT' } @@ -70,6 +72,7 @@ var BOOL_OPTS = [ 'logBody', 'errorOnAbortedRequests', 'instrument', + 'asyncHooks', 'ff_captureFrame', 'sourceContext' ] diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js new file mode 100644 index 00000000000..0429414665b --- /dev/null +++ b/lib/instrumentation/async-hooks.js @@ -0,0 +1,35 @@ +'use strict' + +const asyncHooks = require('async_hooks') + +module.exports = function (ins) { + const asyncHook = asyncHooks.createHook({init, destroy}) + const transactions = new Map() + + Object.defineProperty(ins, 'currentTransaction', { + get: function () { + const asyncId = asyncHooks.executionAsyncId() + return transactions.has(asyncId) ? transactions.get(asyncId) : null + }, + set: function (trans) { + const asyncId = asyncHooks.executionAsyncId() + transactions.set(asyncId, trans) + } + }) + + 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 + + transactions.set(asyncId, ins.currentTransaction) + } + + function destroy (asyncId) { + if (!transactions.has(asyncId)) return // in case type === TIMERWRAP + transactions.delete(asyncId) + } +} diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index 139df8ec750..4e8a8b66e4d 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.asyncHooks && semver.gte(process.version, '8.2.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 2b79193c59b..0dd808f6f90 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 f0844ad776c..82be380b4bc 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], + ['asyncHooks', 'ASYNC_HOOKS', true], ['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 00000000000..ad8cfacb60d --- /dev/null +++ b/test/instrumentation/async-hooks.js @@ -0,0 +1,120 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false, + 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.2.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 00000000000..ea0e7cefebc --- /dev/null +++ b/test/instrumentation/github-issue-75.js @@ -0,0 +1,71 @@ +'use strict' + +var agent = require('../..').start({ + appName: 'test', + captureExceptions: false, + 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 } +}